-
Notifications
You must be signed in to change notification settings - Fork 383
Description
Description
Microsoft-Extensions-Logging’s LoggingEventSource is created with EventSourceSettings.EtwSelfDescribingEventFormat (TraceLogging).
In TraceLogging mode, the ETW header Version is always 0, regardless of the [Event(..., Version = 2)] attribute.
In TraceEventExtensions.GetLogMessageJsonEventData, the code currently checks:
if (traceEvent.Version >= 2)
{
activityTraceId = (string)traceEvent.PayloadValue(8);
activitySpanId = (string)traceEvent.PayloadValue(9);
activityTraceFlags = (string)traceEvent.PayloadValue(10);
}As a result, the additional correlation fields introduced in .NET 9 (ActivityTraceId, ActivitySpanId, ActivityTraceFlags) are never read, because traceEvent.Version is always 0.
Expected behavior:
Correlation fields should be parsed when present in the event payload.
Proposed fix:
Check for the presence of the fields (by name or payload count), not the event Version. For example:
int idxTraceId = traceEvent.PayloadIndex("ActivityTraceId");
if (idxTraceId >= 0)
{
int idxSpanId = traceEvent.PayloadIndex("ActivitySpanId");
int idxFlags = traceEvent.PayloadIndex("ActivityTraceFlags");
activityTraceId = (string)traceEvent.PayloadValue(idxTraceId);
activitySpanId = (string)traceEvent.PayloadValue(idxSpanId);
activityTraceFlags = (string)traceEvent.PayloadValue(idxFlags);
}This way:
- On .NET 8 and earlier: fields not present → values remain null.
- On .NET 9+: fields are parsed correctly.
Impact:
Currently out-of-process auto-instrumentation scenarios using dotnet-monitor miss important trace correlation information, breaking end-to-end telemetry correlation.
[Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways, Version = 2)]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventCoreSuppressionJustification)]
internal unsafe void FormattedMessage(
Raw Trace Event from Perfview
<Event MSec="144004.0634" PID="58428" PName="Process(58428)" TID="10464" EventName="FormattedMessage"
TimeStamp="08/27/25 19:02:58.537278" ID="65279" Version="0" Keywords="0x0000F00000000004" TimeStampQPC="2,339,271,609,972" QPCTime="0.100us"
Level="Always" ProviderName="Microsoft-Extensions-Logging" ProviderGuid="3ac73b97-af73-50e9-0822-5da4367920d0" ClassicProvider="False" ProcessorNumber="5"
Opcode="0" Task="Default" Channel="11" PointerSize="8"
CPU="5" EventIndex="56" TemplateType="DynamicTraceEventData">
<PrettyPrint>
<Event MSec="144004.0634" PID="58428" PName="Process(58428)" TID="10464" EventName="FormattedMessage" ProviderName="Microsoft-Extensions-Logging" Level="1" FactoryID="1" LoggerName="TelemetryDemo" EventId="0" EventName="" _FormattedMessage="Starting database_query" ActivityTraceId="9381484647bbf5c0021359c6b0d76109" ActivitySpanId="54a959238861c107" ActivityTraceFlags="1"/>
</PrettyPrint>
<Payload Length="194">
0: 1 0 0 0 1 0 0 0 | 54 0 65 0 6c 0 65 0 ........ T.e.l.e.
10: 6d 0 65 0 74 0 72 0 | 79 0 44 0 65 0 6d 0 m.e.t.r. y.D.e.m.
20: 6f 0 0 0 0 0 0 0 | 0 0 53 0 74 0 61 0 o....... ..S.t.a.
30: 72 0 74 0 69 0 6e 0 | 67 0 20 0 64 0 61 0 r.t.i.n. g. .d.a.
40: 74 0 61 0 62 0 61 0 | 73 0 65 0 5f 0 71 0 t.a.b.a. s.e._.q.
50: 75 0 65 0 72 0 79 0 | 0 0 39 0 33 0 38 0 u.e.r.y. ..9.3.8.
60: 31 0 34 0 38 0 34 0 | 36 0 34 0 37 0 62 0 1.4.8.4. 6.4.7.b.
70: 62 0 66 0 35 0 63 0 | 30 0 30 0 32 0 31 0 b.f.5.c. 0.0.2.1.
80: 33 0 35 0 39 0 63 0 | 36 0 62 0 30 0 64 0 3.5.9.c. 6.b.0.d.
90: 37 0 36 0 31 0 30 0 | 39 0 0 0 35 0 34 0 7.6.1.0. 9...5.4.
a0: 61 0 39 0 35 0 39 0 | 32 0 33 0 38 0 38 0 a.9.5.9. 2.3.8.8.
b0: 36 0 31 0 63 0 31 0 | 30 0 37 0 0 0 31 0 6.1.c.1. 0.7...1.
c0: 0 0 | ..
</Payload>
</Event>