EventPipe doesn't properly serialize all types handled by EventSource ETW TraceLogging
- Dominant language
- C#
- Stars
- 18.3k
- Forks
- 5.6k
- PR merge metrics
- PR metrics pending
Description
### Description
EventPipe is intended to allow serializing all the same data as EventSource using ETW but testing and code review revealed quite a few cases that aren't properly handled. In each case EventPipe either fails to produce NetTrace metadata describing the event parameter or it produces bad metadata that doesn't accurately describe what was serialized.
This issue is tracking several related but separate bugs:
- [ ] - A self-describing EventSource serializes booleans as 1 byte but the Boolean NetTrace metadata implies they are 4 bytes.
- [ ] - DateTimeOffset doesn't produces any metadata. [GetTypeCodeExtended](https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeMetadataGenerator.cs,256) returns Object but this data type is serialized as an 8 byte tick count.
- [ ] - TimeSpan doesn't produces any metadata. [GetTypeCodeExtended](https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeMetadataGenerator.cs,256) returns Object but this data type is serialized as an 8 byte tick count.
- [ ] - Decimal is serialized by converting it to a double and writing 8 bytes, but EventPipe encodes it in metadata as the Decimal type which implies 16 bytes.
- [ ] - Nullable doesn't produce any metadata. [GetTypeCodeExtended](https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeMetadataGenerator.cs,256) returns Object but casting the TraceLoggingTypeInfo to InvokeTypeInfo fails.
- [ ] - Arrays of non-scalar types don't produce any metadata. TraceLogging encodes these as ArrayTypeInfo (not ScalarArrayTypeInfo) and the GenerateMetadata code doesn't include any case to handle that.
- [ ] - Complex types don't produce the correct metadata for any property that isn't a scalar or another complex type. In this repro we show a scalar array property but it could have been Enumerable, Nullable, non-scalar array, decimal, DateTime, DateTimeOffset, or TimeSpan too.
### Reproduction Steps
Run this code:
```C#
using Microsoft.Diagnostics.NETCore.Client;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing.Session;
using System.Diagnostics.Tracing;
namespace ConsoleApp55
{
internal class Program
{
static bool readyReceived = false;
static bool allEventsReceived = false;
static void Main(string[] args)
{
DiagnosticsClient client = new DiagnosticsClient(Environment.ProcessId);
bool testEventPipe = true;
EventPipeSession? session = null;
TraceEventSession? etwSession = null;
if (testEventPipe)
{
session = client.StartEventPipeSession(new[] {
new EventPipeProvider("MyEventSource", EventLevel.Informational)
}, requestRundown: false);
EventPipeEventSource source = new EventPipeEventSource(session.EventStream);
source.Dynamic.All += PrintEvent;
Task.Run(() => source.Process());
}
else
{
etwSession = new TraceEventSession("MyETWSession");
etwSession.EnableProvider("MyEventSource", TraceEventLevel.Informational);
etwSession.Source.Dynamic.All += PrintEvent;
Task.Run(() => etwSession.Source.Process());
}
while (!readyReceived)
{
MyEventSource.Log.Ready();
Thread.Sleep(100);
}
MyEventSource.Log.WriteBool(true, 15);
MyEventSource.Log.WriteDateTimeOffset(new DateTimeOffset(2024, 1, 1, 12, 0, 0, TimeSpan.FromHours(-5)));
MyEventSource.Log.WriteTimeSpan(TimeSpan.FromHours(1.5));
MyEventSource.Log.WriteDecimal(123.45M);
MyEventSource.Log.WriteNullable(null);
MyEventSource.Log.WriteNullable(42);
MyEventSource.Log.WriteStructArray(new Data[] {
new Data { Id = 1, Name = "Alice" },
new Data { Id = 2, Name = "Bob" }
});
MyEventSource.Log.WriteDataWithArray(new DataWithArray { Id = 1, Name = "Charlie", Scores = new int[] { 100, 95, 90 } });
MyEventSource.Log.Complete();
while(!allEventsReceived)
{
Thread.Sleep(100);
}
session?.Stop();
etwSession?.Stop();
Console.ReadLine();
}
public static void PrintEvent(TraceEvent obj)
{
if (obj.EventName == "Ready")
{
readyReceived = true;
}
else if (obj.EventName == "Complete")
{
Console.WriteLine("All events received.");
allEventsReceived = true;
}
else
{
Console.WriteLine($"{obj.EventName} event received.");
for (int i = 0; i < obj.PayloadNames.Length; i++)
{
Console.WriteLine($" {obj.PayloadNames[i]}: {obj.PayloadValue(i)}");
}
}
}
}
[EventSource(Name = "MyEventSource")]
public class MyEventSource : EventSource
{
public static MyEventSource Log = new MyEventSource();
public MyEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFormat) { }
[Event(1, Level = EventLevel.Informational)]
public void Ready()
{
WriteEvent(1);
}
[Event(2, Level = EventLevel.Informational)]
public void Complete()
{
WriteEvent(2);
}
[Event(3, Level = EventLevel.Informational)]
public void WriteBool(bool flag, int num)
{
WriteEvent(3, flag, num);
}
[Event(4, Level = EventLevel.Informational)]
public void WriteDateTime(DateTime time)
{
WriteEvent(4, time);
}
[Event(5)]
public void WriteDateTimeOffset(DateTimeOffset timeOff)
{
WriteEvent(5, timeOff);
}
[Event(6)]
public void WriteTimeSpan(TimeSpan ts)
{
WriteEvent(6, ts);
}
[Event(7, Level = EventLevel.Informational)]
public void WriteDecimal(decimal dec)
{
WriteEvent(7, dec);
}
[Event(8, Level = EventLevel.Informational)]
public void WriteNullable(int? num)
{
WriteEvent(8, num);
}
[Event(10, Level = EventLevel.Informational)]
public void WriteStructArray(Data[] data)
{
WriteEvent(10, data);
}
[Event(11, Level = EventLevel.Informational)]
public void WriteDataWithArray(DataWithArray data)
{
WriteEvent(11, data);
}
}
[EventData]
public struct Data
{
public int Id;
public string Name;
}
[EventData]
public struct DataWithArray
{
public int[] Scores { get; set; }
public int Id { get; set; }
public string Name { get; set; }
}
}
```
### Expected behavior
If the app ran properly you should see output that looks like this:
```
WriteBool event received.
flag: True
num: 15
WriteDateTimeOffset event received.
timeOff: { "Ticks":"1/1/2024 4:00:00 AM", "Offset":"-180000000000" }
WriteTimeSpan event received.
ts: 54000000000
WriteDecimal event received.
dec: 123.45
WriteNullable event received.
num: { "HasValue":False, "Value":0 }
WriteNullable event received.
num: { "HasValue":True, "Value":42 }
WriteDataWithArray event received.
data: { "Scores":[ 100, 95, 90 ], "Id":1, "Name":"Charlie" }
All events received.
```
You can set `bool testEventPipe = false;` near the top of the repro program Main() function to run the repro against ETW instead and it will print this output.
### Actual behavior
The test outputs:
```
WriteBool event received.
flag: True
num: 50563328
```
Notice that num is wrong and all the other events are missing.
### Regression?
As far as I can tell all these issues have existed in prior releases, likely for as long as EventPipe existed.
### Known Workarounds
You can use ETW instead of EventPipe or you can use alternate data types in the events.
### Configuration
I tested with .NET 9, windows, x64 but I suspect any .NET build that supports EventPipe, any OS, any arch would repro it.
### Other information
A significant contributing factor for all these issues is that the [EventPipe metadata generator code](https://source.dot.net/#System.Private.CoreLib/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeMetadataGenerator.cs,254) primarily reasons about types using System.Type and GetExtendedTypeCode() rather than TraceLoggingTypeInfo. In the places where it does use TraceLoggingTypeInfo it still probes for individual concrete types rather than making polymoprhic calls. TraceLoggingTypeInfo has many different cases to take into account and trying to maintain a 2nd version of the same logic has lead to numerous discrepances.
Contributor guide
Assessment
This issue has not been assessed yet.