Skip to content

Commit 15751e1

Browse files
CodeBlanchrzikm
CodeBlanch
authored and
rzikm
committed
[Logging.EventSource] Add trace correlation fields (dotnet#103655)
* Add trace correlation fields to Microsoft.Extensions.Logging.EventSource. * Code review. * Code review. * Test fix.
1 parent 7067da0 commit 15751e1

File tree

3 files changed

+224
-69
lines changed

3 files changed

+224
-69
lines changed

‎src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLogger.cs

Lines changed: 50 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
using System;
55
using System.Buffers;
66
using System.Collections.Generic;
7+
using System.Diagnostics;
78
using System.Diagnostics.Tracing;
89
using System.IO;
910
using System.Text;
@@ -57,23 +58,58 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
5758
{
5859
return;
5960
}
61+
62+
bool formattedMessageEventEnabled = _eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.FormattedMessage);
63+
bool messageEventEnabled = _eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.Message);
64+
bool jsonMessageEventEnabled = _eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.JsonMessage);
65+
66+
if (!formattedMessageEventEnabled
67+
&& !messageEventEnabled
68+
&& !jsonMessageEventEnabled)
69+
{
70+
return;
71+
}
72+
6073
string? message = null;
6174

75+
Activity? activity = Activity.Current;
76+
string activityTraceId;
77+
string activitySpanId;
78+
string activityTraceFlags;
79+
if (activity != null && activity.IdFormat == ActivityIdFormat.W3C)
80+
{
81+
activityTraceId = activity.TraceId.ToHexString();
82+
activitySpanId = activity.SpanId.ToHexString();
83+
activityTraceFlags = activity.ActivityTraceFlags == ActivityTraceFlags.None
84+
? "0"
85+
: "1";
86+
}
87+
else
88+
{
89+
activityTraceId = string.Empty;
90+
activitySpanId = string.Empty;
91+
activityTraceFlags = string.Empty;
92+
}
93+
6294
// See if they want the formatted message
63-
if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.FormattedMessage))
95+
if (formattedMessageEventEnabled)
6496
{
6597
message = formatter(state, exception);
98+
6699
_eventSource.FormattedMessage(
67100
logLevel,
68101
_factoryID,
69102
CategoryName,
70103
eventId.Id,
71104
eventId.Name,
72-
message);
105+
message,
106+
activityTraceId,
107+
activitySpanId,
108+
activityTraceFlags);
73109
}
74110

75111
// See if they want the message as its component parts.
76-
if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.Message))
112+
if (messageEventEnabled)
77113
{
78114
ExceptionInfo exceptionInfo = GetExceptionInfo(exception);
79115
IReadOnlyList<KeyValuePair<string, string?>> arguments = GetProperties(state);
@@ -85,11 +121,14 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
85121
eventId.Id,
86122
eventId.Name,
87123
exceptionInfo,
88-
arguments);
124+
arguments,
125+
activityTraceId,
126+
activitySpanId,
127+
activityTraceFlags);
89128
}
90129

91130
// See if they want the json message
92-
if (_eventSource.IsEnabled(EventLevel.Critical, LoggingEventSource.Keywords.JsonMessage))
131+
if (jsonMessageEventEnabled)
93132
{
94133
string exceptionJson = "{}";
95134
if (exception != null)
@@ -104,8 +143,9 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
104143
};
105144
exceptionJson = ToJson(exceptionInfoData);
106145
}
146+
107147
IReadOnlyList<KeyValuePair<string, string?>> arguments = GetProperties(state);
108-
message ??= formatter(state, exception);
148+
109149
_eventSource.MessageJson(
110150
logLevel,
111151
_factoryID,
@@ -114,7 +154,10 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
114154
eventId.Name,
115155
exceptionJson,
116156
ToJson(arguments),
117-
message);
157+
message ?? formatter(state, exception),
158+
activityTraceId,
159+
activitySpanId,
160+
activityTraceFlags);
118161
}
119162
}
120163

‎src/libraries/Microsoft.Extensions.Logging.EventSource/src/LoggingEventSource.cs

Lines changed: 109 additions & 58 deletions
Original file line numberDiff line numberDiff line change
@@ -128,50 +128,81 @@ private LoggingEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFo
128128
/// FormattedMessage() is called when ILogger.Log() is called. and the FormattedMessage keyword is active
129129
/// This only gives you the human readable formatted message.
130130
/// </summary>
131-
[Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
131+
[Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways, Version = 2)]
132132
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
133133
Justification = WriteEventCoreSuppressionJustification)]
134-
internal unsafe void FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, string FormattedMessage)
134+
internal unsafe void FormattedMessage(
135+
LogLevel Level,
136+
int FactoryID,
137+
string LoggerName,
138+
int EventId,
139+
string? EventName,
140+
string? FormattedMessage,
141+
string ActivityTraceId,
142+
string ActivitySpanId,
143+
string ActivityTraceFlags)
135144
{
136-
if (IsEnabled())
145+
Debug.Assert(LoggerName != null);
146+
Debug.Assert(ActivityTraceId != null);
147+
Debug.Assert(ActivitySpanId != null);
148+
Debug.Assert(ActivityTraceFlags != null);
149+
150+
EventName ??= string.Empty;
151+
FormattedMessage ??= string.Empty;
152+
153+
fixed (char* loggerName = LoggerName)
154+
fixed (char* eventName = EventName)
155+
fixed (char* formattedMessage = FormattedMessage)
156+
fixed (char* activityTraceId = ActivityTraceId)
157+
fixed (char* activitySpanId = ActivitySpanId)
158+
fixed (char* activityTraceFlags = ActivityTraceFlags)
137159
{
138-
LoggerName ??= "";
139-
EventName ??= "";
140-
FormattedMessage ??= "";
141-
142-
fixed (char* loggerName = LoggerName)
143-
fixed (char* eventName = EventName)
144-
fixed (char* formattedMessage = FormattedMessage)
145-
{
146-
const int eventDataCount = 6;
147-
EventData* eventData = stackalloc EventData[eventDataCount];
148-
149-
SetEventData(ref eventData[0], ref Level);
150-
SetEventData(ref eventData[1], ref FactoryID);
151-
SetEventData(ref eventData[2], ref LoggerName, loggerName);
152-
SetEventData(ref eventData[3], ref EventId);
153-
SetEventData(ref eventData[4], ref EventName, eventName);
154-
SetEventData(ref eventData[5], ref FormattedMessage, formattedMessage);
155-
156-
WriteEventCore(1, eventDataCount, eventData);
157-
}
160+
const int eventDataCount = 9;
161+
EventData* eventData = stackalloc EventData[eventDataCount];
162+
163+
SetEventData(ref eventData[0], ref Level);
164+
SetEventData(ref eventData[1], ref FactoryID);
165+
SetEventData(ref eventData[2], ref LoggerName, loggerName);
166+
SetEventData(ref eventData[3], ref EventId);
167+
SetEventData(ref eventData[4], ref EventName, eventName);
168+
SetEventData(ref eventData[5], ref FormattedMessage, formattedMessage);
169+
SetEventData(ref eventData[6], ref ActivityTraceId, activityTraceId);
170+
SetEventData(ref eventData[7], ref ActivitySpanId, activitySpanId);
171+
SetEventData(ref eventData[8], ref ActivityTraceFlags, activityTraceFlags);
172+
173+
WriteEventCore(1, eventDataCount, eventData);
158174
}
159175
}
160176

161177
/// <summary>
162178
/// Message() is called when ILogger.Log() is called. and the Message keyword is active
163179
/// This gives you the logged information in a programmatic format (arguments are key-value pairs)
164180
/// </summary>
165-
[Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways)]
181+
[Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways, Version = 2)]
166182
[DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties, typeof(KeyValuePair<string, string>))]
167183
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
168184
Justification = WriteEventDynamicDependencySuppressionJustification)]
169-
internal void Message(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string?>> Arguments)
185+
internal void Message(
186+
LogLevel Level,
187+
int FactoryID,
188+
string LoggerName,
189+
int EventId,
190+
string? EventName,
191+
ExceptionInfo Exception,
192+
IEnumerable<KeyValuePair<string, string?>> Arguments,
193+
string ActivityTraceId,
194+
string ActivitySpanId,
195+
string ActivityTraceFlags)
170196
{
171-
if (IsEnabled())
172-
{
173-
WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments);
174-
}
197+
Debug.Assert(LoggerName != null);
198+
Debug.Assert(Exception != null);
199+
Debug.Assert(ActivityTraceId != null);
200+
Debug.Assert(ActivitySpanId != null);
201+
Debug.Assert(ActivityTraceFlags != null);
202+
203+
EventName ??= string.Empty;
204+
205+
WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments, ActivityTraceId, ActivitySpanId, ActivityTraceFlags);
175206
}
176207

177208
/// <summary>
@@ -212,39 +243,57 @@ internal unsafe void ActivityStop(int ID, int FactoryID, string LoggerName)
212243
}
213244
}
214245

215-
[Event(5, Keywords = Keywords.JsonMessage, Level = EventLevel.LogAlways)]
246+
[Event(5, Keywords = Keywords.JsonMessage, Level = EventLevel.LogAlways, Version = 2)]
216247
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
217248
Justification = WriteEventCoreSuppressionJustification)]
218-
internal unsafe void MessageJson(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, string ExceptionJson, string ArgumentsJson, string FormattedMessage)
249+
internal unsafe void MessageJson(
250+
LogLevel Level,
251+
int FactoryID,
252+
string LoggerName,
253+
int EventId,
254+
string? EventName,
255+
string ExceptionJson,
256+
string ArgumentsJson,
257+
string? FormattedMessage,
258+
string ActivityTraceId,
259+
string ActivitySpanId,
260+
string ActivityTraceFlags)
219261
{
220-
if (IsEnabled())
262+
Debug.Assert(LoggerName != null);
263+
Debug.Assert(ExceptionJson != null);
264+
Debug.Assert(ArgumentsJson != null);
265+
Debug.Assert(ActivityTraceId != null);
266+
Debug.Assert(ActivitySpanId != null);
267+
Debug.Assert(ActivityTraceFlags != null);
268+
269+
EventName ??= string.Empty;
270+
FormattedMessage ??= string.Empty;
271+
272+
fixed (char* loggerName = LoggerName)
273+
fixed (char* eventName = EventName)
274+
fixed (char* exceptionJson = ExceptionJson)
275+
fixed (char* argumentsJson = ArgumentsJson)
276+
fixed (char* formattedMessage = FormattedMessage)
277+
fixed (char* activityTraceId = ActivityTraceId)
278+
fixed (char* activitySpanId = ActivitySpanId)
279+
fixed (char* activityTraceFlags = ActivityTraceFlags)
221280
{
222-
LoggerName ??= "";
223-
EventName ??= "";
224-
ExceptionJson ??= "";
225-
ArgumentsJson ??= "";
226-
FormattedMessage ??= "";
227-
228-
fixed (char* loggerName = LoggerName)
229-
fixed (char* eventName = EventName)
230-
fixed (char* exceptionJson = ExceptionJson)
231-
fixed (char* argumentsJson = ArgumentsJson)
232-
fixed (char* formattedMessage = FormattedMessage)
233-
{
234-
const int eventDataCount = 8;
235-
EventData* eventData = stackalloc EventData[eventDataCount];
236-
237-
SetEventData(ref eventData[0], ref Level);
238-
SetEventData(ref eventData[1], ref FactoryID);
239-
SetEventData(ref eventData[2], ref LoggerName, loggerName);
240-
SetEventData(ref eventData[3], ref EventId);
241-
SetEventData(ref eventData[4], ref EventName, eventName);
242-
SetEventData(ref eventData[5], ref ExceptionJson, exceptionJson);
243-
SetEventData(ref eventData[6], ref ArgumentsJson, argumentsJson);
244-
SetEventData(ref eventData[7], ref FormattedMessage, formattedMessage);
245-
246-
WriteEventCore(5, eventDataCount, eventData);
247-
}
281+
const int eventDataCount = 11;
282+
EventData* eventData = stackalloc EventData[eventDataCount];
283+
284+
SetEventData(ref eventData[0], ref Level);
285+
SetEventData(ref eventData[1], ref FactoryID);
286+
SetEventData(ref eventData[2], ref LoggerName, loggerName);
287+
SetEventData(ref eventData[3], ref EventId);
288+
SetEventData(ref eventData[4], ref EventName, eventName);
289+
SetEventData(ref eventData[5], ref ExceptionJson, exceptionJson);
290+
SetEventData(ref eventData[6], ref ArgumentsJson, argumentsJson);
291+
SetEventData(ref eventData[7], ref FormattedMessage, formattedMessage);
292+
SetEventData(ref eventData[8], ref ActivityTraceId, activityTraceId);
293+
SetEventData(ref eventData[9], ref ActivitySpanId, activitySpanId);
294+
SetEventData(ref eventData[10], ref ActivityTraceFlags, activityTraceFlags);
295+
296+
WriteEventCore(5, eventDataCount, eventData);
248297
}
249298
}
250299

@@ -505,6 +554,8 @@ private static unsafe void SetEventData<T>(ref EventData eventData, ref T value,
505554
{
506555
string str = (value as string)!;
507556
#if DEBUG
557+
Debug.Assert(str != null);
558+
508559
fixed (char* rePinnedString = str)
509560
{
510561
Debug.Assert(pinnedString == rePinnedString);

0 commit comments

Comments
 (0)