using System.Diagnostics.Tracing;
using System.Text;
using Microsoft.Diagnostics.NETCore.Client;
+using Microsoft.Diagnostics.Tracing.Parsers;
using Microsoft.Extensions.Logging;
namespace Microsoft.Diagnostics.Monitoring.EventPipe
private readonly string _filterSpecs;
private readonly long _keywords;
private readonly EventLevel _level;
+ private readonly bool _collectScopes;
/// <summary>
/// Creates a new logging source configuration.
/// </summary>
- public LoggingSourceConfiguration(LogLevel level, LogMessageType messageType, IDictionary<string, LogLevel?> filterSpecs, bool useAppFilters)
+ public LoggingSourceConfiguration(LogLevel level, LogMessageType messageType, IDictionary<string, LogLevel?> filterSpecs, bool useAppFilters,
+ bool collectScopes)
{
RequestRundown = false;
_filterSpecs = ToFilterSpecsString(filterSpecs, useAppFilters);
_keywords = (long)ToKeywords(messageType);
_level = ToEventLevel(level);
+ _collectScopes = collectScopes;
}
public override IList<EventPipeProvider> GetProviders()
{
- return new List<EventPipeProvider>()
+ List<EventPipeProvider> providers = new()
{
new EventPipeProvider(
MicrosoftExtensionsLoggingProviderName,
}
)
};
+
+ if (_collectScopes)
+ {
+ // Activity correlation
+ providers.Add(new EventPipeProvider(
+ TplEventSource,
+ EventLevel.Informational,
+ (long)TplEtwProviderTraceEventParser.Keywords.TasksFlowActivityIds));
+ }
+
+ return providers;
}
private static string ToFilterSpecsString(IDictionary<string, LogLevel?> filterSpecs, bool useAppFilters)
Settings.LogLevel,
LogMessageType.FormattedMessage | LogMessageType.JsonMessage,
Settings.FilterSpecs,
- Settings.UseAppFilters);
+ Settings.UseAppFilters,
+ Settings.CollectScopes);
}
catch (NotSupportedException ex)
{
{
string lastFormattedMessage = string.Empty;
- Dictionary<Guid, LogActivityItem> logActivities = new();
- Stack<Guid> stack = new();
+ //
+ // We enable TplEventSource's TasksFlowActivityIds as part of our configuration to enable activity correlation.
+ // This means that each time an event start occurs the current ActivityId will branch creating a new one with a RelatedActivityId equal to where it branched from.
+ // Combining this with the fact that scopes are handled as ActivityJson/{Start,Stop} means the ActivityId will branch each time a scope starts.
+ // When a log message occurs, it'll have an ActivityId equal to the latest applicable scope.
+ //
+ // By maintaining a tree with the branching data, we can construct the full scope for a log message:
+ // - Each time the ActivityId branches, create a node in the tree with it's parent being the node corresponding to the RelatedActivityId.
+ // - Each node has corresponding scope data.
+ // - When a log message occurs, grab the node with the corresponding ActivityId and backtrack to the root of the tree. Each node visited is included as part of the log's scope.
+ //
+ // NOTE: There are edge cases with concurrent traces, this is described in greater detail above our backtracking code.
+ //
+ Dictionary<Guid, LogScopeItem> activityIdToScope = new();
+
+ if (Settings.CollectScopes)
+ {
+ eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "ActivityJson/Start", (traceEvent) => {
+ if (traceEvent.ActivityID == Guid.Empty)
+ {
+ // Unexpected
+ return;
+ }
- eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "ActivityJson/Start", (traceEvent) => {
- int factoryId = (int)traceEvent.PayloadByName("FactoryID");
- string categoryName = (string)traceEvent.PayloadByName("LoggerName");
- string argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
+ string argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
- // TODO: Store this information by logger factory id
- LogActivityItem item = new()
- {
- ActivityID = traceEvent.ActivityID,
- ScopedObject = new LogObject(JsonDocument.Parse(argsJson).RootElement),
- };
+ // TODO: Store this information by logger factory id
+ LogScopeItem item = new()
+ {
+ ActivityID = traceEvent.ActivityID,
+ ScopedObject = new LogObject(JsonDocument.Parse(argsJson).RootElement),
+ };
- if (stack.Count > 0)
- {
- Guid parentId = stack.Peek();
- if (logActivities.TryGetValue(parentId, out LogActivityItem parentItem))
+ if (activityIdToScope.TryGetValue(traceEvent.RelatedActivityID, out LogScopeItem parentItem))
{
item.Parent = parentItem;
}
- }
- stack.Push(traceEvent.ActivityID);
- logActivities[traceEvent.ActivityID] = item;
- });
-
- eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "ActivityJson/Stop", (traceEvent) => {
- int factoryId = (int)traceEvent.PayloadByName("FactoryID");
- string categoryName = (string)traceEvent.PayloadByName("LoggerName");
+ if (activityIdToScope.Count < Settings.ScopeLimit || activityIdToScope.ContainsKey(traceEvent.ActivityID))
+ {
+ activityIdToScope[traceEvent.ActivityID] = item;
+ }
+ });
- //If we begin collection in the middle of a request, we can receive a stop without having a start.
- if (stack.Count > 0)
- {
- stack.Pop();
- logActivities.Remove(traceEvent.ActivityID);
- }
- });
+ eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "ActivityJson/Stop", (traceEvent) => {
+ // Not all stopped event ActivityIds will exist in our tree since there may be scopes already active when we start the trace session.
+ _ = activityIdToScope.Remove(traceEvent.ActivityID);
+ });
+ }
eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) => {
// Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson
ILogger logger = _factory.CreateLogger(categoryName);
List<IDisposable> scopes = new();
- if (logActivities.TryGetValue(traceEvent.ActivityID, out LogActivityItem logActivityItem))
+ //
+ // The MessageJson event will occur with an ActivityId equal to the most relevant activity branch and we can backtrack to the root of the tree
+ // to grab all applicable scopes (where each node we visit is an applicable scope).
+ //
+ // Ideally the ActivityId will always exist in our tree, however if another trace is ongoing that is interested in an event start
+ // within the same async context as our log message then there will be nodes+edges that our tree is unaware of.
+ // This is because TplEventSource's TasksFlowActivityIds is a singleton implementation that is shared for all traces,
+ // regardless of if the other traces have TasksFlowActivityIds enabled.
+ //
+ // In this scenario there's still a chance that only a single branch has occurred and we're the first event logged with the newly branched ActivityId.
+ // In which case we can use the RelatedActivityId to find our way back onto the tree.
+ //
+ // If not then we will be operating on a subtree without a way of getting back to the root node and will only have a subset (if any) of the
+ // applicable scopes.
+ //
+ if (activityIdToScope.TryGetValue(traceEvent.ActivityID, out LogScopeItem scopeItem) ||
+ activityIdToScope.TryGetValue(traceEvent.RelatedActivityID, out scopeItem))
{
- // REVIEW: Does order matter here? We're combining everything anyways.
- while (logActivityItem != null)
+ while (scopeItem != null)
{
- scopes.Add(logger.BeginScope(logActivityItem.ScopedObject));
+ scopes.Add(logger.BeginScope(scopeItem.ScopedObject));
- logActivityItem = logActivityItem.Parent;
+ scopeItem = scopeItem.Parent;
}
}
return state.ToString();
}
- private class LogActivityItem
+ private class LogScopeItem
{
public Guid ActivityID { get; set; }
public LogObject ScopedObject { get; set; }
- public LogActivityItem Parent { get; set; }
+ public LogScopeItem Parent { get; set; }
}
}
}
{
private const string AppLoggerCategoryName = "AppLoggerCategory";
- public static int Main(string[] args)
+ public static async Task<int> Main(string[] args)
{
int pid = Process.GetCurrentProcess().Id;
string pipeServerName = args.Length > 0 ? args[0] : null;
}).ConfigureAwait(true);
}
- TestBodyCore(customCategoryLogger, appCategoryLogger);
+ await TestBodyCore(customCategoryLogger, appCategoryLogger).ConfigureAwait(false);
Console.WriteLine($"{pid} EventPipeTracee: signal end of test data");
Console.Out.Flush();
}
// TODO At some point we may want parameters to choose different test bodies.
- private static void TestBodyCore(ILogger customCategoryLogger, ILogger appCategoryLogger)
+ private static async Task TestBodyCore(ILogger customCategoryLogger, ILogger appCategoryLogger)
{
- //Json data is always converted to strings for ActivityStart events.
- using (IDisposable scope = customCategoryLogger.BeginScope(new Dictionary<string, object> {
+ TaskCompletionSource secondSetScopes = new(TaskCreationOptions.RunContinuationsAsynchronously);
+ TaskCompletionSource firstFinishedLogging = new(TaskCreationOptions.RunContinuationsAsynchronously);
+ TaskCompletionSource secondFinishedLogging = new(TaskCreationOptions.RunContinuationsAsynchronously);
+
+ Task firstTask = Task.Run(async () => {
+ using (IDisposable scope = customCategoryLogger.BeginScope(new Dictionary<string, object> {
{ "IntValue", "5" },
{ "BoolValue", "true" },
{ "StringValue", "test" } }.ToList()))
- {
- customCategoryLogger.LogInformation("Some warning message with {Arg}", 6);
- }
+ {
+ // Await for the other task to add its scopes.
+ await secondSetScopes.Task.ConfigureAwait(false);
+
+ customCategoryLogger.LogInformation("Some warning message with {Arg}", 6);
+
+ // Signal other task to log
+ firstFinishedLogging.SetResult();
+
+ // Do not dispose scopes until the other task is done
+ await secondFinishedLogging.Task.ConfigureAwait(false);
+ }
+ });
+
+ Task secondTask = Task.Run(async () => {
+ using (IDisposable scope = customCategoryLogger.BeginScope(new Dictionary<string, object> {
+ { "IntValue", "6" },
+ { "BoolValue", "false" },
+ { "StringValue", "string" } }.ToList()))
+ {
+ // Signal that we added our scopes and wait for the other task to log
+ secondSetScopes.SetResult();
+ await firstFinishedLogging.Task.ConfigureAwait(false);
+ customCategoryLogger.LogInformation("Some other message with {Arg}", 7);
+ secondFinishedLogging.SetResult();
+ }
+ });
+ await firstTask.ConfigureAwait(false);
+ await secondTask.ConfigureAwait(false);
+
+ //Json data is always converted to strings for ActivityStart events.
customCategoryLogger.LogWarning(new EventId(7, "AnotherEventId"), "Another message");
appCategoryLogger.LogInformation("Information message.");
Assert.Equal(string.Empty, result.EventName);
Validate(result.Scopes, ("BoolValue", "true"), ("StringValue", "test"), ("IntValue", "5"));
Validate(result.Arguments, ("Arg", "6"));
+
+ message = reader.ReadLine();
+ Assert.NotNull(message);
+
+ result = JsonSerializer.Deserialize<LoggerTestResult>(message);
+ Assert.Equal("Some other message with 7", result.Message);
+ Assert.Equal(LoggerRemoteTestName, result.Category);
+ Assert.Equal("Information", result.LogLevel);
+ Assert.Equal(0, result.EventId);
+ Assert.Equal(string.Empty, result.EventName);
+ Validate(result.Scopes, ("BoolValue", "false"), ("StringValue", "string"), ("IntValue", "6"));
+ Validate(result.Arguments, ("Arg", "7"));
}
private static void ValidateLoggerRemoteCategoryWarningMessage(StreamReader reader)
projects / platform / core / dotnet / diagnostics.git / commitdiff