Skip to content

Commit

Permalink
[Logging.EventSource] Add trace correlation fields (dotnet#103655)
Browse files Browse the repository at this point in the history 
* Add trace correlation fields to Microsoft.Extensions.Logging.EventSource.

* Code review.

* Code review.

* Test fix.
  • Loading branch information
@CodeBlanch @rzikm
CodeBlanch authored and rzikm committed Jun 24, 2024
1 parent 7067da0 commit 15751e1
Show file tree
Hide file tree
Showing 3 changed files with 224 additions and 69 deletions.
57 changes: 50 additions & 7 deletions src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -57,23 +58,58 @@ public void Log<TState>(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<KeyValuePair<string, string?>> arguments = GetProperties(state);
Expand All @@ -85,11 +121,14 @@ public void Log<TState>(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)
Expand All @@ -104,8 +143,9 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
};
exceptionJson = ToJson(exceptionInfoData);
}

IReadOnlyList<KeyValuePair<string, string?>> arguments = GetProperties(state);
message ??= formatter(state, exception);

_eventSource.MessageJson(
logLevel,
_factoryID,
Expand All @@ -114,7 +154,10 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
eventId.Name,
exceptionJson,
ToJson(arguments),
message);
message ?? formatter(state, exception),
activityTraceId,
activitySpanId,
activityTraceFlags);
}
}

Expand Down
167 changes: 109 additions & 58 deletions src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -128,50 +128,81 @@ 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.
/// </summary>
[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);
}
}

/// <summary>
/// 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)
/// </summary>
[Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways)]
[Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways, Version = 2)]
[DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties, typeof(KeyValuePair<string, string>))]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventDynamicDependencySuppressionJustification)]
internal void Message(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string?>> Arguments)
internal void Message(
LogLevel Level,
int FactoryID,
string LoggerName,
int EventId,
string? EventName,
ExceptionInfo Exception,
IEnumerable<KeyValuePair<string, string?>> 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);
}

/// <summary>
Expand Down Expand Up @@ -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);
}
}

Expand Down Expand Up @@ -505,6 +554,8 @@ private static unsafe void SetEventData<T>(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);
Expand Down
Loading

0 comments on commit 15751e1

Please sign in to comment.