tsai
/
tye
mirror of https://github.com/dotnet/tye.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity
Browse Source

Refactor diagnostics collector 

- more modular
- nullability
- supports arbitrary filtering instead of just PID
pull/440/head
Ryan Nowak 6 years ago
parent
aa305c3df2
commit
d1d516da34
18 changed files with 1088 additions and 821 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Split View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 6
      src/Microsoft.Tye.Core/HostOptions.cs
  2. 4
      src/Microsoft.Tye.Extensions/Zipkin/ZipkinExtension.cs
  3. 51
      src/Microsoft.Tye.Hosting.Diagnostics/DiagnosticOptions.cs
  4. 815
      src/Microsoft.Tye.Hosting.Diagnostics/DiagnosticsCollector.cs
  5. 80
      src/Microsoft.Tye.Hosting.Diagnostics/DiagnosticsProvider.cs
  6. 20
      src/Microsoft.Tye.Hosting.Diagnostics/Logging/LogObject.cs
  7. 236
      src/Microsoft.Tye.Hosting.Diagnostics/LoggingSink.cs
  8. 55
      src/Microsoft.Tye.Hosting.Diagnostics/MetricSink.cs
  9. 4
      src/Microsoft.Tye.Hosting.Diagnostics/Metrics/CounterPayload.cs
  10. 4
      src/Microsoft.Tye.Hosting.Diagnostics/Metrics/IncrementingCounterPayload.cs
  11. 8
      src/Microsoft.Tye.Hosting.Diagnostics/Microsoft.Tye.Hosting.Diagnostics.csproj
  12. 39
      src/Microsoft.Tye.Hosting.Diagnostics/ReplicaInfo.cs
  13. 371
      src/Microsoft.Tye.Hosting.Diagnostics/TracingSink.cs
  14. 139
      src/Microsoft.Tye.Hosting.Diagnostics/WellKnownEventSources.cs
  15. 17
      src/Microsoft.Tye.Hosting/EventPipeDiagnosticsRunner.cs
  16. 49
      src/Microsoft.Tye.Hosting/TyeHost.cs
  17. 7
      src/tye/Program.RunCommand.cs
  18. 4
      test/Test.Infrastructure/TestHelpers.cs

6
src/Microsoft.Tye.Core/HostOptions.cs
View File

@ -12,13 +12,13 @@ namespace Microsoft.Tye
public List<string> Debug { get; } = new List<string>();
public (string Key, string Value) DistributedTraceProvider { get; set; }
public string? DistributedTraceProvider { get; set; }
public bool Docker { get; set; }
public (string Key, string Value) LoggingProvider { get; set; }
public string? LoggingProvider { get; set; }
public (string Key, string Value) MetricsProvider { get; set; }
public string? MetricsProvider { get; set; }
public bool NoBuild { get; set; }

4
src/Microsoft.Tye.Extensions/Zipkin/ZipkinExtension.cs
View File

@ -53,9 +53,9 @@ namespace Microsoft.Tye.Extensions.Zipkin
}
}
if (context.Options!.DistributedTraceProvider.Key is null)
if (context.Options!.DistributedTraceProvider is null)
{
context.Options.DistributedTraceProvider = ("zipkin", "http://localhost:9411");
context.Options.DistributedTraceProvider = "zipkin=http://localhost:9411";
}
}

51
src/Microsoft.Tye.Hosting.Diagnostics/DiagnosticOptions.cs
View File

@ -2,64 +2,13 @@
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.Logging;
namespace Microsoft.Tye.Hosting.Diagnostics
{
public class DiagnosticOptions
{
public (string Key, string Value) LoggingProvider { get; set; }
public (string Key, string Value) DistributedTraceProvider { get; set; }
public (string Key, string Value) MetricsProvider { get; set; }
public static (string, string) GetProvider(string text)
{
if (string.IsNullOrEmpty(text))
{
return (null, null);
}
var pair = text.Split('=');
if (pair.Length < 2)
{
return (pair[0].Trim(), null);
}
return (pair[0].Trim(), pair[1].Trim());
}
public void DumpDiagnostics(ILogger logger)
{
var (logProviderKey, logProviderValue) = LoggingProvider;
var (dTraceProviderKey, dTraceProviderValue) = DistributedTraceProvider;
switch (logProviderKey?.ToLowerInvariant())
{
case "elastic":
logger.LogInformation("logs: Using ElasticSearch at {URL}", logProviderValue);
break;
case "ai":
logger.LogInformation("logs: Using ApplicationInsights instrumentation key {InstrumentationKey}", logProviderValue);
break;
case "console":
logger.LogInformation("logs: Using console logs");
break;
case "seq":
logger.LogInformation("logs: Using Seq at {URL}", logProviderValue);
break;
default:
break;
}
switch (dTraceProviderKey?.ToLowerInvariant())
{
case "zipkin":
logger.LogInformation("dtrace: Using Zipkin at URL {URL}", dTraceProviderValue);
break;
default:
break;
}
}
}
}

815
src/Microsoft.Tye.Hosting.Diagnostics/DiagnosticsCollector.cs
View File

@ -5,193 +5,94 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.IO;
using System.Linq;
using System.Text.Json;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Tye.Hosting.Diagnostics.Logging;
using Microsoft.Tye.Hosting.Diagnostics.Metrics;
using Microsoft.Diagnostics.NETCore.Client;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing.Parsers;
using Microsoft.Extensions.Logging;
using OpenTelemetry.Exporter.Zipkin;
using OpenTelemetry.Trace;
using OpenTelemetry.Trace.Export;
using Serilog;
using static Microsoft.Tye.Hosting.Diagnostics.WellKnownEventSources;
namespace Microsoft.Tye.Hosting.Diagnostics
{
public class DiagnosticsCollector
{
// This list of event sources needs to be extensible
private static readonly string MicrosoftExtensionsLoggingProviderName = "Microsoft-Extensions-Logging";
private static readonly string SystemRuntimeEventSourceName = "System.Runtime";
private static readonly string MicrosoftAspNetCoreHostingEventSourceName = "Microsoft.AspNetCore.Hosting";
private static readonly string GrpcAspNetCoreServer = "Grpc.AspNetCore.Server";
private static readonly string DiagnosticSourceEventSource = "Microsoft-Diagnostics-DiagnosticSource";
private static readonly string TplEventSource = "System.Threading.Tasks.TplEventSource";
// This is the list of events for distributed tracing
private static readonly string DiagnosticFilterString = "\"" +
"Microsoft.AspNetCore/Microsoft.AspNetCore.Hosting.HttpRequestIn.Start@Activity1Start:-" +
"Request.Scheme" +
";Request.Host" +
";Request.PathBase" +
";Request.QueryString" +
";Request.Path" +
";Request.Method" +
";ActivityStartTime=*Activity.StartTimeUtc.Ticks" +
";ActivityParentId=*Activity.ParentId" +
";ActivityId=*Activity.Id" +
";ActivitySpanId=*Activity.SpanId" +
";ActivityTraceId=*Activity.TraceId" +
";ActivityParentSpanId=*Activity.ParentSpanId" +
";ActivityIdFormat=*Activity.IdFormat" +
"\r\n" +
"Microsoft.AspNetCore/Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop@Activity1Stop:-" +
"Response.StatusCode" +
";ActivityDuration=*Activity.Duration.Ticks" +
";ActivityId=*Activity.Id" +
"\r\n" +
"HttpHandlerDiagnosticListener/System.Net.Http.HttpRequestOut@Event:-" +
"\r\n" +
"HttpHandlerDiagnosticListener/System.Net.Http.HttpRequestOut.Start@Activity2Start:-" +
"Request.RequestUri" +
";Request.Method" +
";Request.RequestUri.Host" +
";Request.RequestUri.Port" +
";ActivityStartTime=*Activity.StartTimeUtc.Ticks" +
";ActivityId=*Activity.Id" +
";ActivitySpanId=*Activity.SpanId" +
";ActivityTraceId=*Activity.TraceId" +
";ActivityParentSpanId=*Activity.ParentSpanId" +
";ActivityIdFormat=*Activity.IdFormat" +
";ActivityId=*Activity.Id" +
"\r\n" +
"HttpHandlerDiagnosticListener/System.Net.Http.HttpRequestOut.Stop@Activity2Stop:-" +
";ActivityDuration=*Activity.Duration.Ticks" +
";ActivityId=*Activity.Id" +
"\r\n" +
"\"";
private readonly Microsoft.Extensions.Logging.ILogger _logger;
private readonly DiagnosticOptions _options;
public DiagnosticsCollector(Microsoft.Extensions.Logging.ILogger logger, DiagnosticOptions options)
public DiagnosticsCollector(Microsoft.Extensions.Logging.ILogger logger)
{
_logger = logger;
_options = options;
}
public void ProcessEvents(
string applicationName,
string serviceName,
int processId,
string replicaName,
IDictionary<string, string> metrics,
CancellationToken cancellationToken)
{
var hasEventPipe = false;
public LoggingSink? LoggingSink { get; set; }
for (var i = 0; i < 10; ++i)
public MetricSink? MetricSink { get; set; }
public TracingSink? TracingSink { get; set; }
public TimeSpan SelectProcessTimeout { get; set; } = TimeSpan.FromSeconds(5);
public Task CollectAsync(ReplicaInfo replicaInfo, CancellationToken cancellationToken)
{
// The diagnostic collection process does lots of synchronous processing. Explicitly
// create a thread so we don't starve thread pool.
var tcs = new TaskCompletionSource<object?>();
var thread = new Thread(() =>
{
if (DiagnosticsClient.GetPublishedProcesses().Contains(processId))
try
{
hasEventPipe = true;
break;
Collect(replicaInfo, cancellationToken);
tcs.SetResult(null);
}
catch (OperationCanceledException)
{
tcs.SetCanceled();
}
catch (Exception ex)
{
tcs.SetException(ex);
}
});
if (cancellationToken.IsCancellationRequested)
thread.Start();
return tcs.Task;
}
public void Collect(ReplicaInfo replicaInfo, CancellationToken cancellationToken)
{
var start = DateTime.UtcNow;
var processId = (int?)null;
while (DateTime.UtcNow < start + SelectProcessTimeout && !cancellationToken.IsCancellationRequested)
{
processId = SelectProcess(replicaInfo);
if (processId.HasValue)
{
return;
_logger.LogInformation("Selected process {PID}.", processId);
break;
}
_logger.LogInformation("No process was selected. Waiting.");
Thread.Sleep(500);
}
if (!hasEventPipe)
if (processId is null)
{
_logger.LogInformation("Process id {PID}, does not support event pipe", processId);
_logger.LogInformation("Failed to select a process after {Timeout}.", SelectProcessTimeout);
return;
}
_logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", replicaName, processId);
// Create the logger factory for this replica
using var loggerFactory = LoggerFactory.Create(builder => ConfigureLogging(serviceName, replicaName, builder));
var processor = new SimpleSpanProcessor(CreateSpanExporter(serviceName));
var providers = new List<EventPipeProvider>()
{
// Runtime Metrics
new EventPipeProvider(
SystemRuntimeEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary<string, string>() {
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
MicrosoftAspNetCoreHostingEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary<string, string>() {
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
GrpcAspNetCoreServer,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary<string, string>() {
{ "EventCounterIntervalSec", "1" }
}
),
// Application Metrics
new EventPipeProvider(
applicationName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary<string, string>() {
{ "EventCounterIntervalSec", "1" }
}
),
// Logging
new EventPipeProvider(
MicrosoftExtensionsLoggingProviderName,
EventLevel.LogAlways,
(long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage)
),
// When we get here we've chosen the desired process.
_logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", replicaInfo.Replica, processId);
// Distributed Tracing
// Activity correlation
new EventPipeProvider(TplEventSource,
keywords: 0x80,
eventLevel: EventLevel.LogAlways),
// Diagnostic source events
new EventPipeProvider(DiagnosticSourceEventSource,
keywords: 0x1 | 0x2,
eventLevel: EventLevel.Verbose,
arguments: new Dictionary<string,string>
{
{ "FilterAndPayloadSpecs", DiagnosticFilterString }
})
};
var providers = CreateDefaultProviders();
providers.Add(CreateStandardProvider(replicaInfo.AssemblyName));
while (!cancellationToken.IsCancellationRequested)
{
EventPipeSession session = null;
var client = new DiagnosticsClient(processId);
var session = (EventPipeSession?)null;
var client = new DiagnosticsClient(processId.Value);
try
{
@ -207,7 +108,7 @@ namespace Microsoft.Tye.Hosting.Diagnostics
{
try
{
session.Stop();
session?.Stop();
}
catch (EndOfStreamException)
{
@ -234,18 +135,28 @@ namespace Microsoft.Tye.Hosting.Diagnostics
using var _ = cancellationToken.Register(() => StopSession());
var disposables = new List<IDisposable>();
try
{
var source = new EventPipeEventSource(session.EventStream);
// Distributed Tracing
HandleDistributedTracingEvents(source, processor);
if (TracingSink is object)
{
disposables.Add(TracingSink.Attach(source, replicaInfo));
}
// Metrics
HandleEventCounters(source, metrics);
if (MetricSink is object)
{
disposables.Add(MetricSink.Attach(source, replicaInfo));
}
// Logging
HandleLoggingEvents(source, loggerFactory, replicaName);
if (LoggingSink is object)
{
disposables.Add(LoggingSink.Attach(source, replicaInfo));
}
source.Process();
}
@ -260,604 +171,44 @@ namespace Microsoft.Tye.Hosting.Diagnostics
finally
{
session?.Dispose();
}
}
_logger.LogInformation("Event pipe collection completed for {ServiceName} on process id {PID}", replicaName, processId);
}
private void HandleLoggingEvents(EventPipeEventSource source, ILoggerFactory loggerFactory, string replicaName)
{
var lastFormattedMessage = "";
var logActivities = new Dictionary<Guid, LogActivityItem>();
var stack = new Stack<Guid>();
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStart/Start", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// TODO: Store this information by logger factory id
var item = new LogActivityItem
{
ActivityID = traceEvent.ActivityID,
ScopedObject = new LogObject(JsonDocument.Parse(argsJson).RootElement),
};
if (stack.TryPeek(out var parentId) && logActivities.TryGetValue(parentId, out var parentItem))
{
item.Parent = parentItem;
}
stack.Push(traceEvent.ActivityID);
logActivities[traceEvent.ActivityID] = item;
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStop/Stop", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
stack.Pop();
logActivities.Remove(traceEvent.ActivityID);
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var exceptionJson = (string)traceEvent.PayloadByName("ExceptionJson");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// There's a bug that causes some of the columns to get mixed up
if (eventName.StartsWith("{"))
{
argsJson = exceptionJson;
exceptionJson = eventName;
eventName = null;
}
if (string.IsNullOrEmpty(argsJson))
{
return;
}
Exception exception = null;
var logger = loggerFactory.CreateLogger(categoryName);
var scopes = new List<IDisposable>();
if (logActivities.TryGetValue(traceEvent.ActivityID, out var logActivityItem))
{
// REVIEW: Does order matter here? We're combining everything anyways.
while (logActivityItem != null)
foreach (var disposable in disposables)
{
scopes.Add(logger.BeginScope(logActivityItem.ScopedObject));
logActivityItem = logActivityItem.Parent;
disposable.Dispose();
}
}
}
try
{
if (exceptionJson != "{}")
{
var exceptionMessage = JsonSerializer.Deserialize<JsonElement>(exceptionJson);
exception = new LoggerException(exceptionMessage);
}
var message = JsonSerializer.Deserialize<JsonElement>(argsJson);
if (message.TryGetProperty("{OriginalFormat}", out var formatElement))
{
var formatString = formatElement.GetString();
var formatter = new LogValuesFormatter(formatString);
var args = new object[formatter.ValueNames.Count];
for (var i = 0; i < args.Length; i++)
{
if (!message.TryGetProperty(formatter.ValueNames[i], out var argValue))
{
// We couldn't find the parsed property in the original message, it's likely that this is a JSON object or something else
// being logged, or some other format that just looks like the formatted message. Stop here and log the formatted message
var obj = new LogObject(message, lastFormattedMessage);
logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback);
break;
}
args[i] = argValue.GetString();
}
logger.Log(logLevel, new EventId(eventId, eventName), exception, formatString, args);
}
else
{
var obj = new LogObject(message, lastFormattedMessage);
logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback);
}
}
catch (Exception ex)
{
_logger.LogDebug(ex, "Error processing log entry for {ServiceName}", replicaName);
}
finally
{
scopes.ForEach(d => d.Dispose());
}
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "FormattedMessage", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, FormattedMessage
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var formattedMessage = (string)traceEvent.PayloadByName("FormattedMessage");
if (string.IsNullOrEmpty(formattedMessage))
{
formattedMessage = eventName;
eventName = "";
}
lastFormattedMessage = formattedMessage;
});
_logger.LogInformation("Event pipe collection completed for {ServiceName} on process id {PID}", replicaInfo.Replica, processId);
}
private void HandleEventCounters(EventPipeEventSource source, IDictionary<string, string> metrics)
private static int? SelectProcess(ReplicaInfo replicaInfo)
{
source.Dynamic.All += traceEvent =>
var processIds = DiagnosticsClient.GetPublishedProcesses();
var processes = processIds.Select(pid =>
{
try
{
// Metrics
if (traceEvent.EventName.Equals("EventCounters"))
{
var payloadVal = (IDictionary<string, object>)traceEvent.PayloadValue(0);
var eventPayload = (IDictionary<string, object>)payloadVal["Payload"];
var payload = CounterPayload.FromPayload(eventPayload);
metrics[traceEvent.ProviderName + "/" + payload.Name] = payload.Value;
}
return Process.GetProcessById(pid);
}
catch (Exception ex)
catch (Exception) // Can fail due to timing.
{
_logger.LogError(ex, "Error processing counter for {ProviderName}:{EventName}", traceEvent.ProviderName, traceEvent.EventName);
return null;
}
};
}
private static void HandleDistributedTracingEvents(EventPipeEventSource source, SpanProcessor processor)
{
var activities = new Dictionary<string, ActivityItem>();
})
.Where(p => p is object)
.ToArray();
source.Dynamic.All += traceEvent =>
try
{
if (traceEvent.EventName == "Activity1Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
if (TryCreateActivity(arguments, out var item))
{
string method = null;
string path = null;
string host = null;
string pathBase = null;
string queryString = null;
string scheme = null;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "Path")
{
path = value;
}
else if (key == "Method")
{
method = value;
}
else if (key == "Host")
{
host = value;
}
else if (key == "PathBase")
{
pathBase = value;
}
else if (key == "Scheme")
{
scheme = value;
}
else if (key == "QueryString")
{
queryString = value;
}
}
item.Name = path;
item.Kind = SpanKind.Server;
item.Attributes[SpanAttributeConstants.HttpUrlKey] = scheme + "://" + host + pathBase + path + queryString;
item.Attributes[SpanAttributeConstants.HttpMethodKey] = method;
item.Attributes[SpanAttributeConstants.HttpPathKey] = path;
activities[item.Id] = item;
}
}
}
if (traceEvent.EventName == "Activity1Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
var (activityId, duration) = GetActivityStop(arguments);
var statusCode = 0;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "StatusCode")
{
statusCode = int.Parse(value);
}
}
if (activityId != null && activities.TryGetValue(activityId, out var item))
{
item.Attributes[SpanAttributeConstants.HttpStatusCodeKey] = statusCode;
item.EndTime = item.StartTime + duration;
var spanData = new SpanData(item.Name,
new SpanContext(item.TraceId, item.SpanId, ActivityTraceFlags.Recorded),
item.ParentSpanId,
item.Kind,
item.StartTime,
item.Attributes,
Enumerable.Empty<Event>(),
Enumerable.Empty<Link>(),
null,
Status.Ok,
item.EndTime);
processor.OnEnd(spanData);
activities.Remove(activityId);
}
}
}
if (traceEvent.EventName == "Activity2Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
string uri = null;
string method = null;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "RequestUri")
{
uri = value;
}
else if (key == "Method")
{
method = value;
}
}
if (TryCreateActivity(arguments, out var item))
{
item.Name = uri;
item.Kind = SpanKind.Client;
item.Attributes[SpanAttributeConstants.HttpUrlKey] = uri;
item.Attributes[SpanAttributeConstants.HttpMethodKey] = method;
activities[item.Id] = item;
}
}
}
if (traceEvent.EventName == "Activity2Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
var (activityId, duration) = GetActivityStop(arguments);
if (activityId != null && activities.TryGetValue(activityId, out var item))
{
item.EndTime = item.StartTime + duration;
var spanData = new SpanData(item.Name,
new SpanContext(item.TraceId, item.SpanId, ActivityTraceFlags.Recorded),
item.ParentSpanId,
item.Kind,
item.StartTime,
item.Attributes,
Enumerable.Empty<Event>(),
Enumerable.Empty<Link>(),
null,
Status.Ok,
item.EndTime);
processor.OnEnd(spanData);
activities.Remove(activityId);
}
}
}
};
}
private static (string ActivityId, TimeSpan Duration) GetActivityStop(IDictionary<string, object>[] arguments)
{
var activityId = default(string);
var duration = default(TimeSpan);
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "ActivityDuration")
{
duration = new TimeSpan(long.Parse(value));
}
return replicaInfo.Selector.Invoke(processes!)?.Id;
}
return (activityId, duration);
}
private static bool TryCreateActivity(IDictionary<string, object>[] arguments, out ActivityItem item)
{
string activityId = null;
string operationName = null;
string spanId = null;
string parentSpanId = null;
string traceId = null;
DateTime startTime = default;
ActivityIdFormat idFormat = default;
foreach (var arg in arguments)
finally
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "ActivityOperationName")
{
operationName = value;
}
else if (key == "ActivitySpanId")
{
spanId = value;
}
else if (key == "ActivityTraceId")
{
traceId = value;
}
else if (key == "ActivityParentSpanId")
foreach (var process in processes!)
{
parentSpanId = value;
process!.Dispose();
}
else if (key == "ActivityStartTime")
{
startTime = new DateTime(long.Parse(value), DateTimeKind.Utc);
}
else if (key == "ActivityIdFormat")
{
idFormat = Enum.Parse<ActivityIdFormat>(value);
}
}
if (string.IsNullOrEmpty(activityId))
{
item = null;
// Not a 3.1 application (we can detect this earlier)
return false;
}
if (idFormat == ActivityIdFormat.Hierarchical)
{
// We need W3C to make it work
item = null;
return false;
}
// This is what open telemetry currently does
// https://github.com/open-telemetry/opentelemetry-dotnet/blob/4ba732af062ddc2759c02aebbc91335aaa3f7173/src/OpenTelemetry.Collector.AspNetCore/Implementation/HttpInListener.cs#L65-L92
item = new ActivityItem()
{
Id = activityId,
Name = operationName,
SpanId = ActivitySpanId.CreateFromString(spanId),
TraceId = ActivityTraceId.CreateFromString(traceId),
ParentSpanId = parentSpanId == "0000000000000000" ? default : ActivitySpanId.CreateFromString(parentSpanId),
StartTime = startTime,
};
return true;
}
// This is the logger factory for application logs. It allows re-routing event pipe collected logs (structured logs)
// to any of the supported sinks, currently (elastic search and app insights)
private void ConfigureLogging(string serviceName, string replicaName, ILoggingBuilder builder)
{
var logProviderKey = _options.LoggingProvider.Key;
var logProviderValue = _options.LoggingProvider.Value;
if (string.Equals(logProviderKey, "elastic", StringComparison.OrdinalIgnoreCase) &&
!string.IsNullOrEmpty(logProviderValue))
{
var loggerConfiguration = new LoggerConfiguration()
.Enrich.WithProperty("Application", serviceName)
.Enrich.WithProperty("Instance", replicaName)
.Enrich.FromLogContext()
.WriteTo.Elasticsearch(logProviderValue);
builder.AddSerilog(loggerConfiguration.CreateLogger());
}
if (string.Equals(logProviderKey, "console", StringComparison.OrdinalIgnoreCase))
{
var loggerConfiguration = new LoggerConfiguration()
.Enrich.WithProperty("Application", serviceName)
.Enrich.WithProperty("Instance", replicaName)
.Enrich.FromLogContext()
.WriteTo.Console(outputTemplate: "[{Instance}]: [{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}");
builder.AddSerilog(loggerConfiguration.CreateLogger());
}
if (string.Equals(logProviderKey, "seq", StringComparison.OrdinalIgnoreCase))
{
var loggerConfiguration = new LoggerConfiguration()
.Enrich.WithProperty("Application", serviceName)
.Enrich.WithProperty("Instance", replicaName)
.Enrich.FromLogContext()
.WriteTo.Seq(logProviderValue);
builder.AddSerilog(loggerConfiguration.CreateLogger());
}
if (string.Equals(logProviderKey, "ai", StringComparison.OrdinalIgnoreCase) &&
!string.IsNullOrEmpty(logProviderValue))
{
builder.AddApplicationInsights(logProviderValue);
}
// REVIEW: How are log levels controlled on the outside?
builder.SetMinimumLevel(LogLevel.Information);
}
private SpanExporter CreateSpanExporter(string serviceName)
{
if (string.Equals(_options.DistributedTraceProvider.Key, "zipkin", StringComparison.OrdinalIgnoreCase) &&
!string.IsNullOrEmpty(_options.DistributedTraceProvider.Value))
{
var zipkin = new ZipkinTraceExporter(new ZipkinTraceExporterOptions
{
ServiceName = serviceName,
Endpoint = new Uri($"{_options.DistributedTraceProvider.Value.TrimEnd('/')}/api/v2/spans")
});
return zipkin;
}
// TODO: Support Jaegar
// TODO: Support ApplicationInsights
return new NullExporter();
}
public class NullExporter : SpanExporter
{
public override Task<ExportResult> ExportAsync(IEnumerable<SpanData> batch, CancellationToken cancellationToken)
{
return Task.FromResult(ExportResult.Success);
}
public override Task ShutdownAsync(CancellationToken cancellationToken)
{
return Task.CompletedTask;
}
}
private class ActivityItem
{
public string Id { get; set; }
public string Name { get; set; }
public ActivityTraceId TraceId { get; set; }
public ActivitySpanId SpanId { get; set; }
public Dictionary<string, object> Attributes { get; } = new Dictionary<string, object>();
public DateTime StartTime { get; set; }
public DateTime EndTime { get; set; }
public SpanKind Kind { get; set; }
public ActivitySpanId ParentSpanId { get; set; }
}
private class LogActivityItem
{
public Guid ActivityID { get; set; }
public LogObject ScopedObject { get; set; }
public LogActivityItem Parent { get; set; }
}
internal static class SpanAttributeConstants
{
public static readonly string ComponentKey = "component";
public static readonly string HttpMethodKey = "http.method";
public static readonly string HttpStatusCodeKey = "http.status_code";
public static readonly string HttpUserAgentKey = "http.user_agent";
public static readonly string HttpPathKey = "http.path";
public static readonly string HttpHostKey = "http.host";
public static readonly string HttpUrlKey = "http.url";
public static readonly string HttpRouteKey = "http.route";
public static readonly string HttpFlavorKey = "http.flavor";
}
internal static class LoggingEventSource
{
/// <summary>
/// This is public from an EventSource consumer point of view, but since these definitions
/// are not needed outside this class
/// </summary>
public static class Keywords
{
/// <summary>
/// Meta events are events about the LoggingEventSource itself (that is they did not come from ILogger
/// </summary>
public const EventKeywords Meta = (EventKeywords)1;
/// <summary>
/// Turns on the 'Message' event when ILogger.Log() is called. It gives the information in a programmatic (not formatted) way
/// </summary>
public const EventKeywords Message = (EventKeywords)2;
/// <summary>
/// Turns on the 'FormatMessage' event when ILogger.Log() is called. It gives the formatted string version of the information.
/// </summary>
public const EventKeywords FormattedMessage = (EventKeywords)4;
/// <summary>
/// Turns on the 'MessageJson' event when ILogger.Log() is called. It gives JSON representation of the Arguments.
/// </summary>
public const EventKeywords JsonMessage = (EventKeywords)8;
}
}
}

80
src/Microsoft.Tye.Hosting.Diagnostics/DiagnosticsProvider.cs
View File

@ -0,0 +1,80 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using System.Collections.Generic;
using System.Diagnostics.CodeAnalysis;
namespace Microsoft.Tye
{
public class DiagnosticsProvider
{
public static readonly IReadOnlyDictionary<string, WellKnownProvider> WellKnownProviders = new Dictionary<string, WellKnownProvider>()
{
{ "ai", new WellKnownProvider("ai", ProviderKind.Logging, "logs: Using ApplicationInsights instrumentation key {InstrumentationKey}") },
{ "elastic", new WellKnownProvider("elastic", ProviderKind.Logging, "logs: Using ElasticSearch at {URL}") },
{ "console", new WellKnownProvider("console", ProviderKind.Logging, "logs: Using console logs") },
{ "seq", new WellKnownProvider("seq", ProviderKind.Logging, "logs: Using Seq at {URL}") },
{ "zipkin", new WellKnownProvider("zipkin", ProviderKind.Tracing, "dtrace: Using Zipkin at URL {URL}") },
};
public static bool TryParse(string text, ProviderKind kind, [MaybeNullWhen(false)] out DiagnosticsProvider provider)
{
if (string.IsNullOrEmpty(text))
{
provider = null!;
return false;
}
var pair = text.Split('=');
if (pair.Length < 2)
{
provider = new DiagnosticsProvider(pair[0].Trim().ToLowerInvariant(), null, kind);
return true;
}
provider = new DiagnosticsProvider(pair[0].Trim().ToLowerInvariant(), pair[1].Trim().ToLowerInvariant(), kind);
return true;
}
public DiagnosticsProvider(string key, string? value, ProviderKind kind)
{
Key = key;
Value = value;
Kind = kind;
}
public string Key { get; }
public bool HasValue => !string.IsNullOrEmpty(Value);
public string? Value { get; }
public ProviderKind Kind { get; }
public enum ProviderKind
{
Logging,
Metrics,
Tracing,
Unknown,
}
public class WellKnownProvider
{
public WellKnownProvider(string key, ProviderKind kind, string logFormat)
{
Key = key;
Kind = kind;
LogFormat = logFormat;
}
public string Key { get; }
public ProviderKind Kind { get; }
public string LogFormat { get; }
}
}
}

20
src/Microsoft.Tye.Hosting.Diagnostics/Logging/LogObject.cs
View File

@ -9,14 +9,14 @@ using System.Text.Json;
namespace Microsoft.Tye.Hosting.Diagnostics.Logging
{
internal class LogObject : IReadOnlyList<KeyValuePair<string, object>>
internal class LogObject : IReadOnlyList<KeyValuePair<string, object?>>
{
internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((LogObject)state).ToString();
private readonly string _formattedMessage;
private List<KeyValuePair<string, object>> _items = new List<KeyValuePair<string, object>>();
private readonly string? _formattedMessage;
private List<KeyValuePair<string, object?>> _items = new List<KeyValuePair<string, object?>>();
public LogObject(JsonElement element, string formattedMessage = null)
public LogObject(JsonElement element, string? formattedMessage = null)
{
foreach (var item in element.EnumerateObject())
{
@ -29,17 +29,17 @@ namespace Microsoft.Tye.Hosting.Diagnostics.Logging
case JsonValueKind.Array:
break;
case JsonValueKind.String:
_items.Add(new KeyValuePair<string, object>(item.Name, item.Value.GetString()));
_items.Add(new KeyValuePair<string, object?>(item.Name, item.Value.GetString()));
break;
case JsonValueKind.Number:
_items.Add(new KeyValuePair<string, object>(item.Name, item.Value.GetInt32()));
_items.Add(new KeyValuePair<string, object?>(item.Name, item.Value.GetInt32()));
break;
case JsonValueKind.False:
case JsonValueKind.True:
_items.Add(new KeyValuePair<string, object>(item.Name, item.Value.GetBoolean()));
_items.Add(new KeyValuePair<string, object?>(item.Name, item.Value.GetBoolean()));
break;
case JsonValueKind.Null:
_items.Add(new KeyValuePair<string, object>(item.Name, null));
_items.Add(new KeyValuePair<string, object?>(item.Name, null));
break;
default:
break;
@ -49,11 +49,11 @@ namespace Microsoft.Tye.Hosting.Diagnostics.Logging
_formattedMessage = formattedMessage;
}
public KeyValuePair<string, object> this[int index] => _items[index];
public KeyValuePair<string, object?> this[int index] => _items[index];
public int Count => _items.Count;
public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
public IEnumerator<KeyValuePair<string, object?>> GetEnumerator()
{
return _items.GetEnumerator();
}

236
src/Microsoft.Tye.Hosting.Diagnostics/LoggingSink.cs
View File

@ -0,0 +1,236 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using System;
using System.Collections.Generic;
using System.Text.Json;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Extensions.Logging;
using Microsoft.Tye.Hosting.Diagnostics.Logging;
using Serilog;
using static Microsoft.Tye.Hosting.Diagnostics.WellKnownEventSources;
namespace Microsoft.Tye.Hosting.Diagnostics
{
public class LoggingSink
{
private readonly Microsoft.Extensions.Logging.ILogger _logger;
private readonly DiagnosticsProvider _provider;
public LoggingSink(Microsoft.Extensions.Logging.ILogger logger, DiagnosticsProvider provider)
{
_logger = logger;
_provider = provider;
}
public IDisposable Attach(EventPipeEventSource source, ReplicaInfo replicaInfo)
{
using var loggerFactory = LoggerFactory.Create(builder => ConfigureLogging(replicaInfo.Service, replicaInfo.Replica, builder));
var lastFormattedMessage = "";
var logActivities = new Dictionary<Guid, LogActivityItem>();
var stack = new Stack<Guid>();
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStart/Start", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// TODO: Store this information by logger factory id
var item = new LogActivityItem(traceEvent.ActivityID, new LogObject(JsonDocument.Parse(argsJson).RootElement));
if (stack.TryPeek(out var parentId) && logActivities.TryGetValue(parentId, out var parentItem))
{
item.Parent = parentItem;
}
stack.Push(traceEvent.ActivityID);
logActivities[traceEvent.ActivityID] = item;
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStop/Stop", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
stack.Pop();
logActivities.Remove(traceEvent.ActivityID);
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var exceptionJson = (string)traceEvent.PayloadByName("ExceptionJson");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// There's a bug that causes some of the columns to get mixed up
if (eventName.StartsWith("{"))
{
argsJson = exceptionJson;
exceptionJson = eventName;
eventName = null;
}
if (string.IsNullOrEmpty(argsJson))
{
return;
}
Exception? exception = null;
var logger = loggerFactory.CreateLogger(categoryName);
var scopes = new List<IDisposable>();
if (logActivities.TryGetValue(traceEvent.ActivityID, out var logActivityItem))
{
// REVIEW: Does order matter here? We're combining everything anyways.
while (logActivityItem != null)
{
scopes.Add(logger.BeginScope(logActivityItem.ScopedObject));
logActivityItem = logActivityItem.Parent;
}
}
try
{
if (exceptionJson != "{}")
{
var exceptionMessage = JsonSerializer.Deserialize<JsonElement>(exceptionJson);
exception = new LoggerException(exceptionMessage);
}
var message = JsonSerializer.Deserialize<JsonElement>(argsJson);
if (message.TryGetProperty("{OriginalFormat}", out var formatElement))
{
var formatString = formatElement.GetString();
var formatter = new LogValuesFormatter(formatString);
var args = new object[formatter.ValueNames.Count];
for (var i = 0; i < args.Length; i++)
{
if (!message.TryGetProperty(formatter.ValueNames[i], out var argValue))
{
// We couldn't find the parsed property in the original message, it's likely that this is a JSON object or something else
// being logged, or some other format that just looks like the formatted message. Stop here and log the formatted message
var obj = new LogObject(message, lastFormattedMessage);
logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback);
break;
}
args[i] = argValue.GetString();
}
logger.Log(logLevel, new EventId(eventId, eventName), exception, formatString, args);
}
else
{
var obj = new LogObject(message, lastFormattedMessage);
logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback);
}
}
catch (Exception ex)
{
_logger.LogDebug(ex, "Error processing log entry for {ServiceName}", replicaInfo.Replica);
}
finally
{
scopes.ForEach(d => d.Dispose());
}
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "FormattedMessage", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, FormattedMessage
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var formattedMessage = (string)traceEvent.PayloadByName("FormattedMessage");
if (string.IsNullOrEmpty(formattedMessage))
{
formattedMessage = eventName;
eventName = "";
}
lastFormattedMessage = formattedMessage;
});
return loggerFactory; // the logger factory will be cleaned up when collection ends.
}
// This is the logger factory for application logs. It allows re-routing event pipe collected logs (structured logs)
// to any of the supported sinks, currently (elastic search and app insights)
private void ConfigureLogging(string serviceName, string replicaName, ILoggingBuilder builder)
{
if (string.Equals(_provider.Key, "elastic", StringComparison.OrdinalIgnoreCase) &&
!string.IsNullOrEmpty(_provider.Value))
{
var loggerConfiguration = new LoggerConfiguration()
.Enrich.WithProperty("Application", serviceName)
.Enrich.WithProperty("Instance", replicaName)
.Enrich.FromLogContext()
.WriteTo.Elasticsearch(_provider.Value);
builder.AddSerilog(loggerConfiguration.CreateLogger());
}
if (string.Equals(_provider.Key, "console", StringComparison.OrdinalIgnoreCase))
{
var loggerConfiguration = new LoggerConfiguration()
.Enrich.WithProperty("Application", serviceName)
.Enrich.WithProperty("Instance", replicaName)
.Enrich.FromLogContext()
.WriteTo.Console(outputTemplate: "[{Instance}]: [{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}");
builder.AddSerilog(loggerConfiguration.CreateLogger());
}
if (string.Equals(_provider.Key, "seq", StringComparison.OrdinalIgnoreCase) &&
!string.IsNullOrEmpty(_provider.Value))
{
var loggerConfiguration = new LoggerConfiguration()
.Enrich.WithProperty("Application", serviceName)
.Enrich.WithProperty("Instance", replicaName)
.Enrich.FromLogContext()
.WriteTo.Seq(_provider.Value);
builder.AddSerilog(loggerConfiguration.CreateLogger());
}
if (string.Equals(_provider.Key, "ai", StringComparison.OrdinalIgnoreCase) &&
!string.IsNullOrEmpty(_provider.Value))
{
builder.AddApplicationInsights(_provider.Value);
}
// REVIEW: How are log levels controlled on the outside?
builder.SetMinimumLevel(LogLevel.Information);
}
private class LogActivityItem
{
public LogActivityItem(Guid activityID, LogObject scopedObject)
{
ActivityID = activityID;
ScopedObject = scopedObject;
}
public Guid ActivityID { get; }
public LogObject ScopedObject { get; }
public LogActivityItem? Parent { get; set; }
}
}
}

55
src/Microsoft.Tye.Hosting.Diagnostics/MetricSink.cs
View File

@ -0,0 +1,55 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using System;
using System.Collections.Generic;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Extensions.Logging;
using Microsoft.Tye.Hosting.Diagnostics.Metrics;
namespace Microsoft.Tye.Hosting.Diagnostics
{
public class MetricSink
{
private readonly ILogger _logger;
public MetricSink(ILogger logger)
{
_logger = logger;
}
public IDisposable Attach(EventPipeEventSource source, ReplicaInfo replicaInfo)
{
var store = replicaInfo.Metrics;
source.Dynamic.All += traceEvent =>
{
try
{
// Metrics
if (traceEvent.EventName.Equals("EventCounters"))
{
var value = (IDictionary<string, object>)traceEvent.PayloadValue(0);
var eventPayload = (IDictionary<string, object>)value["Payload"];
var payload = CounterPayload.FromPayload(eventPayload);
store[traceEvent.ProviderName + "/" + payload.Name] = payload.Value;
}
}
catch (Exception ex)
{
_logger.LogError(ex, "Error processing counter for {ProviderName}:{EventName}", traceEvent.ProviderName, traceEvent.EventName);
}
};
return new NullDisposable();
}
private class NullDisposable : IDisposable
{
public void Dispose() { }
}
}
}

4
src/Microsoft.Tye.Hosting.Diagnostics/Metrics/CounterPayload.cs
View File

@ -10,8 +10,8 @@ namespace Microsoft.Tye.Hosting.Diagnostics.Metrics
{
public CounterPayload(IDictionary<string, object> payloadFields)
{
Name = payloadFields["Name"].ToString();
Value = payloadFields["Mean"].ToString();
Name = payloadFields["Name"].ToString()!;
Value = payloadFields["Mean"].ToString()!;
}
public string Name { get; }

4
src/Microsoft.Tye.Hosting.Diagnostics/Metrics/IncrementingCounterPayload.cs
View File

@ -10,8 +10,8 @@ namespace Microsoft.Tye.Hosting.Diagnostics.Metrics
{
public IncrementingCounterPayload(IDictionary<string, object> payloadFields)
{
Name = payloadFields["Name"].ToString();
Value = payloadFields["Increment"].ToString();
Name = payloadFields["Name"].ToString()!;
Value = payloadFields["Increment"].ToString()!;
}
public string Name { get; }

8
src/Microsoft.Tye.Hosting.Diagnostics/Microsoft.Tye.Hosting.Diagnostics.csproj
View File

@ -5,9 +5,15 @@
<Description>Diagnostics collector and exporter for .NET Core applications.</Description>
<AssemblyName>Microsoft.Tye.Hosting.Diagnostics</AssemblyName>
<PackageId>Microsoft.Tye.Hosting.Diagnostics</PackageId>
<Nullable>disable</Nullable>
</PropertyGroup>
<!--
This project is separate from hosting INTENTIONALLY so that we can have a relatively
small and separate of dependencies for diagnostics sinks. So, avoid putting diagnostics
things into the build/deploy code, and avoid putting build/deploy dependencies
into the diagnostics code.
-->
<ItemGroup Label="Pinned">
<!--
Packages here are pinned to higher versions so that we're using versions that

39
src/Microsoft.Tye.Hosting.Diagnostics/ReplicaInfo.cs
View File

@ -0,0 +1,39 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Diagnostics;
namespace Microsoft.Tye.Hosting.Diagnostics
{
public class ReplicaInfo
{
public ReplicaInfo(
Func<IReadOnlyList<Process>, Process?> selector,
string assemblyName,
string service,
string replica,
ConcurrentDictionary<string, string> metrics)
{
Selector = selector;
AssemblyName = assemblyName;
Service = service;
Replica = replica;
Metrics = metrics;
}
public Func<IReadOnlyList<Process>, Process?> Selector { get; }
public string AssemblyName { get; }
public string Service { get; }
public string Replica { get; }
// TODO - this isn't a great way to pass metrics around.
public ConcurrentDictionary<string, string> Metrics { get; }
}
}

371
src/Microsoft.Tye.Hosting.Diagnostics/TracingSink.cs
View File

@ -0,0 +1,371 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using System.Linq;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Extensions.Logging;
using OpenTelemetry.Exporter.Zipkin;
using OpenTelemetry.Trace;
using OpenTelemetry.Trace.Export;
namespace Microsoft.Tye.Hosting.Diagnostics
{
public class TracingSink
{
private readonly ILogger _logger;
private readonly DiagnosticsProvider _provider;
public TracingSink(ILogger logger, DiagnosticsProvider provider)
{
_logger = logger;
_provider = provider;
}
public IDisposable Attach(EventPipeEventSource source, ReplicaInfo replicaInfo)
{
var exporter = CreateSpanExporter(replicaInfo);
if (exporter is null)
{
return new NullDisposable();
}
var processor = new SimpleSpanProcessor(exporter);
var activities = new Dictionary<string, ActivityItem>();
source.Dynamic.All += traceEvent =>
{
if (traceEvent.EventName == "Activity1Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
if (TryCreateActivity(arguments, out var item))
{
string? method = null;
string? path = null;
string? host = null;
string? pathBase = null;
string? queryString = null;
string? scheme = null;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "Path")
{
path = value;
}
else if (key == "Method")
{
method = value;
}
else if (key == "Host")
{
host = value;
}
else if (key == "PathBase")
{
pathBase = value;
}
else if (key == "Scheme")
{
scheme = value;
}
else if (key == "QueryString")
{
queryString = value;
}
}
item.Name = path;
item.Kind = SpanKind.Server;
item.Attributes[SpanAttributeConstants.HttpUrlKey] = scheme + "://" + host + pathBase + path + queryString;
item.Attributes[SpanAttributeConstants.HttpMethodKey] = method;
item.Attributes[SpanAttributeConstants.HttpPathKey] = path;
activities[item.Id] = item;
}
}
}
if (traceEvent.EventName == "Activity1Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
var (activityId, duration) = GetActivityStop(arguments);
var statusCode = 0;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "StatusCode")
{
statusCode = int.Parse(value);
}
}
if (activityId != null && activities.TryGetValue(activityId, out var item))
{
item.Attributes[SpanAttributeConstants.HttpStatusCodeKey] = statusCode;
item.EndTime = item.StartTime + duration;
var spanData = new SpanData(item.Name,
new SpanContext(item.TraceId, item.SpanId, ActivityTraceFlags.Recorded),
item.ParentSpanId,
item.Kind,
item.StartTime,
item.Attributes,
Enumerable.Empty<Event>(),
Enumerable.Empty<Link>(),
null,
Status.Ok,
item.EndTime);
processor.OnEnd(spanData);
activities.Remove(activityId);
}
}
}
if (traceEvent.EventName == "Activity2Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
string? uri = null;
string? method = null;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "RequestUri")
{
uri = value;
}
else if (key == "Method")
{
method = value;
}
}
if (TryCreateActivity(arguments, out var item))
{
item.Name = uri;
item.Kind = SpanKind.Client;
item.Attributes[SpanAttributeConstants.HttpUrlKey] = uri;
item.Attributes[SpanAttributeConstants.HttpMethodKey] = method;
activities[item.Id] = item;
}
}
}
if (traceEvent.EventName == "Activity2Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary<string, object>[] arguments)
{
var (activityId, duration) = GetActivityStop(arguments);
if (activityId != null && activities.TryGetValue(activityId, out var item))
{
item.EndTime = item.StartTime + duration;
var spanData = new SpanData(
item.Name,
new SpanContext(item.TraceId, item.SpanId, ActivityTraceFlags.Recorded),
item.ParentSpanId,
item.Kind,
item.StartTime,
item.Attributes,
Enumerable.Empty<Event>(),
Enumerable.Empty<Link>(),
null,
Status.Ok,
item.EndTime);
processor.OnEnd(spanData);
activities.Remove(activityId);
}
}
}
};
return new NullDisposable();
}
private static bool TryCreateActivity(IDictionary<string, object>[] arguments, [MaybeNullWhen(false)] out ActivityItem item)
{
string? activityId = null;
string? operationName = null;
string? spanId = null;
string? parentSpanId = null;
string? traceId = null;
DateTime startTime = default;
ActivityIdFormat idFormat = default;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "ActivityOperationName")
{
operationName = value;
}
else if (key == "ActivitySpanId")
{
spanId = value;
}
else if (key == "ActivityTraceId")
{
traceId = value;
}
else if (key == "ActivityParentSpanId")
{
parentSpanId = value;
}
else if (key == "ActivityStartTime")
{
startTime = new DateTime(long.Parse(value), DateTimeKind.Utc);
}
else if (key == "ActivityIdFormat")
{
idFormat = Enum.Parse<ActivityIdFormat>(value);
}
}
if (string.IsNullOrEmpty(activityId))
{
// Not a 3.1 application (we can detect this earlier)
item = null!;
return false;
}
if (idFormat == ActivityIdFormat.Hierarchical)
{
// We need W3C to make it work
item = null!;
return false;
}
// This is what open telemetry currently does
// https://github.com/open-telemetry/opentelemetry-dotnet/blob/4ba732af062ddc2759c02aebbc91335aaa3f7173/src/OpenTelemetry.Collector.AspNetCore/Implementation/HttpInListener.cs#L65-L92
item = new ActivityItem(activityId)
{
Name = operationName,
SpanId = ActivitySpanId.CreateFromString(spanId),
TraceId = ActivityTraceId.CreateFromString(traceId),
ParentSpanId = parentSpanId == "0000000000000000" ? default : ActivitySpanId.CreateFromString(parentSpanId),
StartTime = startTime,
};
return true;
}
private static (string? ActivityId, TimeSpan Duration) GetActivityStop(IDictionary<string, object>[] arguments)
{
var activityId = (string?)null;
var duration = default(TimeSpan);
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "ActivityDuration")
{
duration = new TimeSpan(long.Parse(value));
}
}
return (activityId, duration);
}
private SpanExporter? CreateSpanExporter(ReplicaInfo replicaInfo)
{
if (string.Equals(_provider.Key, "zipkin", StringComparison.OrdinalIgnoreCase) &&
!string.IsNullOrEmpty(_provider.Value))
{
var zipkin = new ZipkinTraceExporter(new ZipkinTraceExporterOptions()
{
ServiceName = replicaInfo.Service,
Endpoint = new Uri($"{_provider.Value.TrimEnd('/')}/api/v2/spans")
});
return zipkin;
}
// TODO: Support Jaegar
// TODO: Support ApplicationInsights
return null;
}
private class ActivityItem
{
public ActivityItem(string id)
{
Id = id;
}
public string Id { get; }
public string? Name { get; set; }
public ActivityTraceId TraceId { get; set; }
public ActivitySpanId SpanId { get; set; }
public Dictionary<string, object?> Attributes { get; } = new Dictionary<string, object?>();
public DateTime StartTime { get; set; }
public DateTime EndTime { get; set; }
public SpanKind Kind { get; set; }
public ActivitySpanId ParentSpanId { get; set; }
}
internal static class SpanAttributeConstants
{
public static readonly string ComponentKey = "component";
public static readonly string HttpMethodKey = "http.method";
public static readonly string HttpStatusCodeKey = "http.status_code";
public static readonly string HttpUserAgentKey = "http.user_agent";
public static readonly string HttpPathKey = "http.path";
public static readonly string HttpHostKey = "http.host";
public static readonly string HttpUrlKey = "http.url";
public static readonly string HttpRouteKey = "http.route";
public static readonly string HttpFlavorKey = "http.flavor";
}
private class NullDisposable : IDisposable
{
public void Dispose() { }
}
}
}

139
src/Microsoft.Tye.Hosting.Diagnostics/WellKnownEventSources.cs
View File

@ -0,0 +1,139 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
// See the LICENSE file in the project root for more information.
using System.Collections.Generic;
using System.Diagnostics.Tracing;
using Microsoft.Diagnostics.NETCore.Client;
using Microsoft.Diagnostics.Tracing.Parsers;
namespace Microsoft.Tye.Hosting.Diagnostics
{
internal static class WellKnownEventSources
{
// This list of event sources needs to be extensible
public static readonly string MicrosoftExtensionsLoggingProviderName = "Microsoft-Extensions-Logging";
public static readonly string SystemRuntimeEventSourceName = "System.Runtime";
public static readonly string MicrosoftAspNetCoreHostingEventSourceName = "Microsoft.AspNetCore.Hosting";
public static readonly string GrpcAspNetCoreServer = "Grpc.AspNetCore.Server";
public static readonly string DiagnosticSourceEventSource = "Microsoft-Diagnostics-DiagnosticSource";
public static readonly string TplEventSource = "System.Threading.Tasks.TplEventSource";
// This is the list of events for distributed tracing
public static readonly string DiagnosticFilterString = "\"" +
"Microsoft.AspNetCore/Microsoft.AspNetCore.Hosting.HttpRequestIn.Start@Activity1Start:-" +
"Request.Scheme" +
";Request.Host" +
";Request.PathBase" +
";Request.QueryString" +
";Request.Path" +
";Request.Method" +
";ActivityStartTime=*Activity.StartTimeUtc.Ticks" +
";ActivityParentId=*Activity.ParentId" +
";ActivityId=*Activity.Id" +
";ActivitySpanId=*Activity.SpanId" +
";ActivityTraceId=*Activity.TraceId" +
";ActivityParentSpanId=*Activity.ParentSpanId" +
";ActivityIdFormat=*Activity.IdFormat" +
"\r\n" +
"Microsoft.AspNetCore/Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop@Activity1Stop:-" +
"Response.StatusCode" +
";ActivityDuration=*Activity.Duration.Ticks" +
";ActivityId=*Activity.Id" +
"\r\n" +
"HttpHandlerDiagnosticListener/System.Net.Http.HttpRequestOut@Event:-" +
"\r\n" +
"HttpHandlerDiagnosticListener/System.Net.Http.HttpRequestOut.Start@Activity2Start:-" +
"Request.RequestUri" +
";Request.Method" +
";Request.RequestUri.Host" +
";Request.RequestUri.Port" +
";ActivityStartTime=*Activity.StartTimeUtc.Ticks" +
";ActivityId=*Activity.Id" +
";ActivitySpanId=*Activity.SpanId" +
";ActivityTraceId=*Activity.TraceId" +
";ActivityParentSpanId=*Activity.ParentSpanId" +
";ActivityIdFormat=*Activity.IdFormat" +
";ActivityId=*Activity.Id" +
"\r\n" +
"HttpHandlerDiagnosticListener/System.Net.Http.HttpRequestOut.Stop@Activity2Stop:-" +
";ActivityDuration=*Activity.Duration.Ticks" +
";ActivityId=*Activity.Id" +
"\r\n" +
"\"";
public static List<EventPipeProvider> CreateDefaultProviders()
{
return new List<EventPipeProvider>()
{
// Runtime Metrics
CreateStandardProvider(SystemRuntimeEventSourceName),
CreateStandardProvider(MicrosoftAspNetCoreHostingEventSourceName),
CreateStandardProvider(GrpcAspNetCoreServer),
// Logging
new EventPipeProvider(
MicrosoftExtensionsLoggingProviderName,
EventLevel.LogAlways,
(long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage)),
// Activity correlation
new EventPipeProvider(
TplEventSource,
keywords: 0x80,
eventLevel: EventLevel.LogAlways),
// Diagnostic source events
new EventPipeProvider(
DiagnosticSourceEventSource,
keywords: 0x1 | 0x2,
eventLevel: EventLevel.Verbose,
arguments: new Dictionary<string,string>
{
{ "FilterAndPayloadSpecs", DiagnosticFilterString }
})
};
}
public static EventPipeProvider CreateStandardProvider(string providerName)
{
return
new EventPipeProvider(
providerName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary<string, string>()
{
{ "EventCounterIntervalSec", "1" }
});
}
private static class LoggingEventSource
{
/// <summary>
/// This is public from an EventSource consumer point of view, but since these definitions
/// are not needed outside this class
/// </summary>
public static class Keywords
{
/// <summary>
/// Meta events are events about the LoggingEventSource itself (that is they did not come from ILogger
/// </summary>
public const EventKeywords Meta = (EventKeywords)1;
/// <summary>
/// Turns on the 'Message' event when ILogger.Log() is called. It gives the information in a programmatic (not formatted) way
/// </summary>
public const EventKeywords Message = (EventKeywords)2;
/// <summary>
/// Turns on the 'FormatMessage' event when ILogger.Log() is called. It gives the formatted string version of the information.
/// </summary>
public const EventKeywords FormattedMessage = (EventKeywords)4;
/// <summary>
/// Turns on the 'MessageJson' event when ILogger.Log() is called. It gives JSON representation of the Arguments.
/// </summary>
public const EventKeywords JsonMessage = (EventKeywords)8;
}
}
}
}

17
src/Microsoft.Tye.Hosting/EventPipeDiagnosticsRunner.cs
View File

@ -9,6 +9,7 @@ using System.Threading.Tasks;
using Microsoft.Tye.Hosting.Diagnostics;
using Microsoft.Tye.Hosting.Model;
using Microsoft.Extensions.Logging;
using System.Linq;
namespace Microsoft.Tye.Hosting
{
@ -71,15 +72,17 @@ namespace Microsoft.Tye.Hosting
StoppingTokenSource = cts,
Thread = new Thread(() =>
{
// TODO: Finding the application name requires msbuild knowledge
_diagnosticsCollector.ProcessEvents(
Path.GetFileNameWithoutExtension(process.Service.Status.ProjectFilePath),
var replicaInfo = new ReplicaInfo(
(processes) => processes.FirstOrDefault(p => p.Id == process.Pid!.Value),
// TODO: Finding the application name requires msbuild knowledge
Path.GetFileNameWithoutExtension(process.Service.Status.ProjectFilePath)!,
process.Service.Description.Name,
process.Pid!.Value,
replica.Name,
replica.Metrics,
cts.Token);
})
replica.Metrics);
_diagnosticsCollector.Collect(replicaInfo, cts.Token);
}),
};
replica.Items[typeof(DiagnosticsState)] = state;

49
src/Microsoft.Tye.Hosting/TyeHost.cs
View File

@ -248,17 +248,26 @@ namespace Microsoft.Tye.Hosting
private static AggregateApplicationProcessor CreateApplicationProcessor(ReplicaRegistry replicaRegistry, HostOptions options, Microsoft.Extensions.Logging.ILogger logger)
{
var diagnostics = new DiagnosticOptions()
var diagnosticsCollector = new DiagnosticsCollector(logger)
{
DistributedTraceProvider = options.DistributedTraceProvider,
LoggingProvider = options.LoggingProvider,
MetricsProvider = options.MetricsProvider,
// Local run always uses metrics for the dashboard
MetricSink = new MetricSink(logger),
};
var diagnosticsCollector = new DiagnosticsCollector(logger, diagnostics);
if (options.LoggingProvider is string &&
DiagnosticsProvider.TryParse(options.LoggingProvider, DiagnosticsProvider.ProviderKind.Logging, out var logging))
{
diagnosticsCollector.LoggingSink = new LoggingSink(logger, logging);
}
if (options.DistributedTraceProvider is string &&
DiagnosticsProvider.TryParse(options.DistributedTraceProvider, DiagnosticsProvider.ProviderKind.Tracing, out var tracing))
{
diagnosticsCollector.TracingSink = new TracingSink(logger, tracing);
}
// Print out what providers were selected and their values
diagnostics.DumpDiagnostics(logger);
DumpDiagnostics(options, logger);
var processors = new List<IApplicationProcessor>
{
@ -337,5 +346,33 @@ namespace Microsoft.Tye.Hosting
_replicaRegistry?.Dispose();
DashboardWebApplication?.Dispose();
}
private static void DumpDiagnostics(HostOptions options, Microsoft.Extensions.Logging.ILogger logger)
{
var providerText = new List<string>();
providerText.AddRange(
new[] { options.DistributedTraceProvider, options.LoggingProvider, options.MetricsProvider }
.Where(p => p is object)
.Cast<string>());
foreach (var text in providerText)
{
if (DiagnosticsProvider.TryParse(text, DiagnosticsProvider.ProviderKind.Unknown, out var provider))
{
if (DiagnosticsProvider.WellKnownProviders.TryGetValue(provider.Key, out var wellKnown))
{
logger.LogInformation(wellKnown.LogFormat, provider.Value);
}
else
{
logger.LogWarning("Unknown diagnostics provider {Key}:{Value}", provider.Key, provider.Value);
}
}
else
{
logger.LogError("Could not parse provider argument: {Arg}", text);
}
}
}
}
}

7
src/tye/Program.RunCommand.cs
View File

@ -99,9 +99,10 @@ namespace Microsoft.Tye
NoBuild = args.NoBuild,
Port = args.Port,
DistributedTraceProvider = DiagnosticOptions.GetProvider(args.Dtrace),
LoggingProvider = DiagnosticOptions.GetProvider(args.Logs),
MetricsProvider = DiagnosticOptions.GetProvider(args.Metrics),
// parsed later by the diagnostics code
DistributedTraceProvider = args.Dtrace,
LoggingProvider = args.Logs,
MetricsProvider = args.Metrics,
};
options.Debug.AddRange(args.Debug);

4
test/Test.Infrastructure/TestHelpers.cs
View File

@ -120,7 +120,7 @@ namespace Test.Infrastructure
if (alreadyStarted == totalReplicas)
{
startedTask.TrySetResult(true);
startedTask!.TrySetResult(true);
}
}
@ -169,7 +169,7 @@ namespace Test.Infrastructure
if (remaining == 0)
{
stoppedTask.TrySetResult(true);
stoppedTask!.TrySetResult(true);
}
}

Write Preview
Loading…
Cancel
Save