Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Logging.EventSource] Add trace correlation fields #103655

Merged
merged 6 commits into from
Jun 22, 2024
Merged

[Logging.EventSource] Add trace correlation fields #103655

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
7ec5342
Add trace correlation fields to Microsoft.Extensions.Logging.EventSou…
CodeBlanch Jun 12, 2024
e68e9a5
Code review.
CodeBlanch Jun 18, 2024
0e968ae
Code review.
CodeBlanch Jun 18, 2024
dc52eb9
Merge remote-tracking branch 'upstream/main' into logging-eventsource…
CodeBlanch Jun 20, 2024
26a9b90
Merge remote-tracking branch 'upstream/main' into logging-eventsource…
CodeBlanch Jun 21, 2024
e69bc64
Test fix.
CodeBlanch Jun 21, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
57 changes: 50 additions & 7 deletions src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs
View file
Open in desktop
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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are we sure we don't want support non W3C cases too?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well for non-W3C TraceId is going to spit out 00000000000000000000000000000000 and SpanId is going to spit out 0000000000000000. We could just push Activity.Id into the events which would include W3C, Hierarchical, and (presumably) anything added in the future. BUT. Accessing Activity.Id will force an allocation in the process being monitored. And it will force consumers to have to inspect the value and understand the possible formats/differences. Probably also the consumers will have to chop up the Id into the individual components. In my world of OTel I don't need hierarchical but if you feel there is a need and the tradeoffs are OK, I'm happy to switch it.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We have been supporting the Hierarchical cases with external logger scopes.

runtime/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactoryScopeProvider.cs

Line 291 in b93061a

public static string GetSpanId(this Activity activity)

Also, will it make sense to add the parent Id to the event as we do in scopes?

CC @noahfalk if he has more insight if we should ignore the Hierarchical cases or not.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just FYI the reason I went with ActivityTraceId, ActivitySpanId, and ActivityTraceFlags is because those are the only things defined on the OTel Logs Data Model for correlation: https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#log-and-event-record-definition

Happy to add other things, but from OTel perspective they aren't required.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd be fine omitting support for hierarichal. Worst case I forsee is we get feedback that someone wants Hierarichal support, we decide the scenario in the request is important and then we add that too in a future release. I think that has a pretty low chance of happening.

{
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
Open in desktop
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);
tarekgh marked this conversation as resolved.
Show resolved Hide resolved

fixed (char* rePinnedString = str)
{
Debug.Assert(pinnedString == rePinnedString);
Expand Down
Loading
Loading