From 649626b3d0c19342c2d0d61d0d8d768725764bd4 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Fri, 21 Jun 2024 17:36:55 -0700 Subject: [PATCH] [Logging.EventSource] Add trace correlation fields (#103655) * Add trace correlation fields to Microsoft.Extensions.Logging.EventSource. * Code review. * Code review. * Test fix. --- .../src/EventSourceLogger.cs | 57 +++++- .../src/LoggingEventSource.cs | 167 ++++++++++++------ .../tests/EventSourceLoggerTest.cs | 69 +++++++- 3 files changed, 224 insertions(+), 69 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs b/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs index b2ad0238529a1..0bfc67c2ef99c 100644 --- a/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs +++ b/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs @@ -4,6 +4,7 @@ using System; using System.Buffers; using System.Collections.Generic; +using System.Diagnostics; using System.Diagnostics.Tracing; using System.IO; using System.Text; @@ -57,23 +58,58 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except { return; } + + bool formattedMessageEventEnabled = _eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.FormattedMessage); + bool messageEventEnabled = _eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.Message); + bool jsonMessageEventEnabled = _eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.JsonMessage); + + if (!formattedMessageEventEnabled + && !messageEventEnabled + && !jsonMessageEventEnabled) + { + return; + } + string? message = null; + Activity? activity = Activity.Current; + string activityTraceId; + string activitySpanId; + string activityTraceFlags; + if (activity != null && activity.IdFormat == ActivityIdFormat.W3C) + { + activityTraceId = activity.TraceId.ToHexString(); + activitySpanId = activity.SpanId.ToHexString(); + activityTraceFlags = activity.ActivityTraceFlags == ActivityTraceFlags.None + ? "0" + : "1"; + } + else + { + activityTraceId = string.Empty; + activitySpanId = string.Empty; + activityTraceFlags = string.Empty; + } + // See if they want the formatted message - if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.FormattedMessage)) + if (formattedMessageEventEnabled) { message = formatter(state, exception); + _eventSource.FormattedMessage( logLevel, _factoryID, CategoryName, eventId.Id, eventId.Name, - message); + message, + activityTraceId, + activitySpanId, + activityTraceFlags); } // See if they want the message as its component parts. - if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.Message)) + if (messageEventEnabled) { ExceptionInfo exceptionInfo = GetExceptionInfo(exception); IReadOnlyList> arguments = GetProperties(state); @@ -85,11 +121,14 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except eventId.Id, eventId.Name, exceptionInfo, - arguments); + arguments, + activityTraceId, + activitySpanId, + activityTraceFlags); } // See if they want the json message - if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.JsonMessage)) + if (jsonMessageEventEnabled) { string exceptionJson = "{}"; if (exception != null) @@ -104,8 +143,9 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except }; exceptionJson = ToJson(exceptionInfoData); } + IReadOnlyList> arguments = GetProperties(state); - message ??= formatter(state, exception); + _eventSource.MessageJson( logLevel, _factoryID, @@ -114,7 +154,10 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except eventId.Name, exceptionJson, ToJson(arguments), - message); + message ?? formatter(state, exception), + activityTraceId, + activitySpanId, + activityTraceFlags); } } diff --git a/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs b/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs index fb2705c80319b..66a95042e84cf 100644 --- a/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs +++ b/src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs @@ -128,33 +128,49 @@ private LoggingEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFo /// FormattedMessage() is called when ILogger.Log() is called. and the FormattedMessage keyword is active /// This only gives you the human readable formatted message. /// - [Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways)] + [Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways, Version = 2)] [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode", Justification = WriteEventCoreSuppressionJustification)] - internal unsafe void FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, string FormattedMessage) + internal unsafe void FormattedMessage( + LogLevel Level, + int FactoryID, + string LoggerName, + int EventId, + string? EventName, + string? FormattedMessage, + string ActivityTraceId, + string ActivitySpanId, + string ActivityTraceFlags) { - if (IsEnabled()) + Debug.Assert(LoggerName != null); + Debug.Assert(ActivityTraceId != null); + Debug.Assert(ActivitySpanId != null); + Debug.Assert(ActivityTraceFlags != null); + + EventName ??= string.Empty; + FormattedMessage ??= string.Empty; + + fixed (char* loggerName = LoggerName) + fixed (char* eventName = EventName) + fixed (char* formattedMessage = FormattedMessage) + fixed (char* activityTraceId = ActivityTraceId) + fixed (char* activitySpanId = ActivitySpanId) + fixed (char* activityTraceFlags = ActivityTraceFlags) { - LoggerName ??= ""; - EventName ??= ""; - FormattedMessage ??= ""; - - fixed (char* loggerName = LoggerName) - fixed (char* eventName = EventName) - fixed (char* formattedMessage = FormattedMessage) - { - const int eventDataCount = 6; - EventData* eventData = stackalloc EventData[eventDataCount]; - - SetEventData(ref eventData[0], ref Level); - SetEventData(ref eventData[1], ref FactoryID); - SetEventData(ref eventData[2], ref LoggerName, loggerName); - SetEventData(ref eventData[3], ref EventId); - SetEventData(ref eventData[4], ref EventName, eventName); - SetEventData(ref eventData[5], ref FormattedMessage, formattedMessage); - - WriteEventCore(1, eventDataCount, eventData); - } + const int eventDataCount = 9; + EventData* eventData = stackalloc EventData[eventDataCount]; + + SetEventData(ref eventData[0], ref Level); + SetEventData(ref eventData[1], ref FactoryID); + SetEventData(ref eventData[2], ref LoggerName, loggerName); + SetEventData(ref eventData[3], ref EventId); + SetEventData(ref eventData[4], ref EventName, eventName); + SetEventData(ref eventData[5], ref FormattedMessage, formattedMessage); + SetEventData(ref eventData[6], ref ActivityTraceId, activityTraceId); + SetEventData(ref eventData[7], ref ActivitySpanId, activitySpanId); + SetEventData(ref eventData[8], ref ActivityTraceFlags, activityTraceFlags); + + WriteEventCore(1, eventDataCount, eventData); } } @@ -162,16 +178,31 @@ internal unsafe void FormattedMessage(LogLevel Level, int FactoryID, string Logg /// Message() is called when ILogger.Log() is called. and the Message keyword is active /// This gives you the logged information in a programmatic format (arguments are key-value pairs) /// - [Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways)] + [Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways, Version = 2)] [DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties, typeof(KeyValuePair))] [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode", Justification = WriteEventDynamicDependencySuppressionJustification)] - internal void Message(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, ExceptionInfo Exception, IEnumerable> Arguments) + internal void Message( + LogLevel Level, + int FactoryID, + string LoggerName, + int EventId, + string? EventName, + ExceptionInfo Exception, + IEnumerable> Arguments, + string ActivityTraceId, + string ActivitySpanId, + string ActivityTraceFlags) { - if (IsEnabled()) - { - WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments); - } + Debug.Assert(LoggerName != null); + Debug.Assert(Exception != null); + Debug.Assert(ActivityTraceId != null); + Debug.Assert(ActivitySpanId != null); + Debug.Assert(ActivityTraceFlags != null); + + EventName ??= string.Empty; + + WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments, ActivityTraceId, ActivitySpanId, ActivityTraceFlags); } /// @@ -212,39 +243,57 @@ internal unsafe void ActivityStop(int ID, int FactoryID, string LoggerName) } } - [Event(5, Keywords = Keywords.JsonMessage, Level = EventLevel.LogAlways)] + [Event(5, Keywords = Keywords.JsonMessage, Level = EventLevel.LogAlways, Version = 2)] [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode", Justification = WriteEventCoreSuppressionJustification)] - internal unsafe void MessageJson(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, string ExceptionJson, string ArgumentsJson, string FormattedMessage) + internal unsafe void MessageJson( + LogLevel Level, + int FactoryID, + string LoggerName, + int EventId, + string? EventName, + string ExceptionJson, + string ArgumentsJson, + string? FormattedMessage, + string ActivityTraceId, + string ActivitySpanId, + string ActivityTraceFlags) { - if (IsEnabled()) + Debug.Assert(LoggerName != null); + Debug.Assert(ExceptionJson != null); + Debug.Assert(ArgumentsJson != null); + Debug.Assert(ActivityTraceId != null); + Debug.Assert(ActivitySpanId != null); + Debug.Assert(ActivityTraceFlags != null); + + EventName ??= string.Empty; + FormattedMessage ??= string.Empty; + + fixed (char* loggerName = LoggerName) + fixed (char* eventName = EventName) + fixed (char* exceptionJson = ExceptionJson) + fixed (char* argumentsJson = ArgumentsJson) + fixed (char* formattedMessage = FormattedMessage) + fixed (char* activityTraceId = ActivityTraceId) + fixed (char* activitySpanId = ActivitySpanId) + fixed (char* activityTraceFlags = ActivityTraceFlags) { - LoggerName ??= ""; - EventName ??= ""; - ExceptionJson ??= ""; - ArgumentsJson ??= ""; - FormattedMessage ??= ""; - - fixed (char* loggerName = LoggerName) - fixed (char* eventName = EventName) - fixed (char* exceptionJson = ExceptionJson) - fixed (char* argumentsJson = ArgumentsJson) - fixed (char* formattedMessage = FormattedMessage) - { - const int eventDataCount = 8; - EventData* eventData = stackalloc EventData[eventDataCount]; - - SetEventData(ref eventData[0], ref Level); - SetEventData(ref eventData[1], ref FactoryID); - SetEventData(ref eventData[2], ref LoggerName, loggerName); - SetEventData(ref eventData[3], ref EventId); - SetEventData(ref eventData[4], ref EventName, eventName); - SetEventData(ref eventData[5], ref ExceptionJson, exceptionJson); - SetEventData(ref eventData[6], ref ArgumentsJson, argumentsJson); - SetEventData(ref eventData[7], ref FormattedMessage, formattedMessage); - - WriteEventCore(5, eventDataCount, eventData); - } + const int eventDataCount = 11; + EventData* eventData = stackalloc EventData[eventDataCount]; + + SetEventData(ref eventData[0], ref Level); + SetEventData(ref eventData[1], ref FactoryID); + SetEventData(ref eventData[2], ref LoggerName, loggerName); + SetEventData(ref eventData[3], ref EventId); + SetEventData(ref eventData[4], ref EventName, eventName); + SetEventData(ref eventData[5], ref ExceptionJson, exceptionJson); + SetEventData(ref eventData[6], ref ArgumentsJson, argumentsJson); + SetEventData(ref eventData[7], ref FormattedMessage, formattedMessage); + SetEventData(ref eventData[8], ref ActivityTraceId, activityTraceId); + SetEventData(ref eventData[9], ref ActivitySpanId, activitySpanId); + SetEventData(ref eventData[10], ref ActivityTraceFlags, activityTraceFlags); + + WriteEventCore(5, eventDataCount, eventData); } } @@ -505,6 +554,8 @@ private static unsafe void SetEventData(ref EventData eventData, ref T value, { string str = (value as string)!; #if DEBUG + Debug.Assert(str != null); + fixed (char* rePinnedString = str) { Debug.Assert(pinnedString == rePinnedString); diff --git a/src/libraries/Microsoft.Extensions.Logging.EventSource/tests/EventSourceLoggerTest.cs b/src/libraries/Microsoft.Extensions.Logging.EventSource/tests/EventSourceLoggerTest.cs index eb4f25eb34fc5..d7cdc0c52e2de 100644 --- a/src/libraries/Microsoft.Extensions.Logging.EventSource/tests/EventSourceLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging.EventSource/tests/EventSourceLoggerTest.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Diagnostics.Tracing; using System.Globalization; using System.IO; @@ -10,7 +11,6 @@ using System.Text.Json; using Microsoft.Extensions.Logging.EventSource; using Xunit; -using Microsoft.Extensions.DependencyInjection; using Newtonsoft.Json; namespace Microsoft.Extensions.Logging.Test @@ -135,7 +135,7 @@ public void FilterSpecs_IncreaseLoggingLevelForOneCategory_DisablesExistingRules var logger2 = loggerFactory.CreateLogger("Logger2"); var logger3 = loggerFactory.CreateLogger("Logger3"); var logger4 = loggerFactory.CreateLogger("Logger4"); - + foreach (LogLevel level in Enum.GetValues(typeof(LogLevel))) { Assert.False(logger.IsEnabled(LogLevel.None)); @@ -195,6 +195,67 @@ public void Logs_AsExpected_WithDefaults() } } + [Theory] + [InlineData(true, true, true)] + [InlineData(true, true, false)] + [InlineData(true, false, true)] + [InlineData(false, true, true)] + [ActiveIssue("https://github.com/dotnet/runtime/issues/73438", typeof(PlatformDetection), nameof(PlatformDetection.IsNativeAot))] + public void Logs_TracingDetailsAsExpected_WithDefaults(bool hasTrace, bool useW3CFormatId, bool sampled) + { + using (var testListener = new TestEventListener()) + { + var factory = CreateLoggerFactory(); + + var listenerSettings = new TestEventListener.ListenerSettings(); + listenerSettings.Keywords = (EventKeywords)(-1); + listenerSettings.FilterSpec = null; + listenerSettings.Level = default(EventLevel); + testListener.EnableEvents(listenerSettings); + + using Activity activity = new Activity("TestOperation"); + + if (hasTrace) + { + if (useW3CFormatId) + { + activity.SetIdFormat(ActivityIdFormat.W3C); + } + else + { + activity.SetIdFormat(ActivityIdFormat.Hierarchical); + } + + activity.Start(); + + if (sampled) + { + activity.ActivityTraceFlags = ActivityTraceFlags.Recorded; + } + } + + var logger = factory.CreateLogger("TestLogger"); + + logger.LogInformation("Hello world"); + + foreach (var eventJson in testListener.Events) + { + if (hasTrace && useW3CFormatId) + { + Assert.Contains($@"""ActivityTraceId"":""{activity.TraceId.ToHexString()}""", eventJson); + Assert.Contains($@"""ActivitySpanId"":""{activity.SpanId.ToHexString()}""", eventJson); + Assert.Contains($@"""ActivityTraceFlags"":""{(activity.Recorded ? "1" : "0")}""", eventJson); + } + else + { + Assert.Contains(@"""ActivityTraceId"":""""", eventJson); + Assert.Contains(@"""ActivitySpanId"":""""", eventJson); + Assert.Contains(@"""ActivityTraceFlags"":""""", eventJson); + } + } + } + } + [Fact] [ActiveIssue("https://github.com/dotnet/runtime/issues/73438", typeof(PlatformDetection), nameof(PlatformDetection.IsNativeAot))] public void Logs_AsExpected_WithDefaults_EnabledEarly() @@ -588,7 +649,7 @@ public void Logs_AsExpected_MessageJson_WithNullString() // Write some MessageJson events with null string. for (var i = 0; i < 100; i++) { - LoggingEventSource.Instance.MessageJson(LogLevel.Trace, 1, "MyLogger", 5, null, null, "testJson", "formattedMessage"); + LoggingEventSource.Instance.MessageJson(LogLevel.Trace, 1, "MyLogger", 5, null, "testJson", "testJson", "formattedMessage", string.Empty, string.Empty, string.Empty); } bool containsNullEventName = false; @@ -605,7 +666,7 @@ public void Logs_AsExpected_MessageJson_WithNullString() } } - Assert.True(containsNullEventName, "EventName and ExceptionJson is supposed to be null but it isn't."); + Assert.True(containsNullEventName, "EventName is supposed to be null but it isn't."); Assert.True(containsFormattedMessage, "FormattedMessage is supposed to be present but it isn't."); } }