WriteEventCore with DateTime has changed behavior in .Net 6.0

[andrew-hampton]

Description

When updating to .NET 6.0, we encountered issues with DateTimes within events containing an incorrect year. It appears that the optimization in pull request #52092 changed the behavior so that it's no longer decoded from a FileTime and is instead decoded using the full tick value.

Reproduction Steps

Write an event using WriteEventCore like the example below

            [Event(1)]
            public unsafe void DateTimeEvent(DateTime dateTime)
            {
                if (this.IsEnabled())
                {
                    var fileTimeVal = dateTime.Year < 1601 ? 0 : dateTime.ToFileTimeUtc();
                    EventSource.EventData* descrs = stackalloc EventSource.EventData[1];
                    descrs[0].DataPointer = (IntPtr)(&fileTimeVal);
                    descrs[0].Size = sizeof(long);
                    WriteEventCore(1, 1, descrs);
                }
            }

Expected behavior

EventWrittenEventArgs payload from an EventTraceListener contains the DateTime matching the input.

Actual behavior

EventWrittenEventArgs payload from an EventTraceListener contains the DateTime, but the year is off by 1600 as it appears to be decoding from ticks rather than file time ticks.

Other information

This appears to be a breaking change from NetCore3.1 and Net 5.0 so seeking guidance on whether this is an expected change in behavior or if this is a bug. Thanks!

[dotnet-issue-labeler]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[andrew-hampton]

Area should be "area-System.Diagnostics.Tracing"

[ghost]

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

When updating to .NET 6.0, we encountered issues with DateTimes within events containing an incorrect year. It appears that the optimization in pull request #52092 changed the behavior so that it's no longer decoded from a FileTime and is instead decoded using the full tick value.

Reproduction Steps

Write an event using WriteEventCore like the example below

            [Event(1)]
            public unsafe void DateTimeEvent(DateTime dateTime)
            {
                if (this.IsEnabled())
                {
                    var fileTimeVal = dateTime.Year < 1601 ? 0 : dateTime.ToFileTimeUtc();
                    EventSource.EventData* descrs = stackalloc EventSource.EventData[1];
                    descrs[0].DataPointer = (IntPtr)(&fileTimeVal);
                    descrs[0].Size = sizeof(long);
                    WriteEventCore(1, 1, descrs);
                }
            }

Expected behavior

EventWrittenEventArgs payload from an EventTraceListener contains the DateTime matching the input.

Actual behavior

EventWrittenEventArgs payload from an EventTraceListener contains the DateTime, but the year is off by 1600 as it appears to be decoding from ticks rather than file time ticks.

Known Workarounds

A workaround is to use dateTime.ToBinary() instead of dateTime.ToFileTimeUtc() to get the value to include within EventData.

Other information

This appears to be a breaking change from NetCore3.1 and Net 5.0 so seeking guidance on whether this is an expected change in behavior or if this is a bug. Thanks!

Author:	andrew-hampton
Assignees:	-
Labels:	area-System.Diagnostics.Tracing, untriaged
Milestone:	-

[MihaZupan]

This was an unintended behavioral change from #52092

DateTime has no test coverage of going through DecodeObjects, as the test is only using the varargs overload.

[tarekgh]

CC @sywhang @noahfalk

[MJSanfelippo]

Hi, any updates on this?

[tommcdon]

@MJSanfelippo this issue is currently on our backlog and we have not yet had time to investigate. Is this workaround sufficient or is this a higher priority issue?

A couple of quick questions:

1. The WriteEventCore repro seems to be writing a long (8 bytes) to the event pipe stream. Are the 8 bytes being truncated or shifted?
2. As mentioned above no datetime is being written to EventPipe. The datetime is being converted to a long using dateTime.ToFileTimeUtc(). Is the problem with the conversion to file offsets? If so, this sounds like a bug in DateTime and not in EventPipe.

[MihaZupan]

@tommcdon it is a bug introduced by #52092 in .NET 6.0, but only affects in-process EventListeners.

The difference is in how the serialized value (long) is de-serialized by DecodeObjects:

• In 5.0, the DateTime would be converted from a long back to a DateTime via DateTime.FromFileTimeUtc
• In 6.0, the value is interpreted as a DateTime directly (i.e. exact number of ticks)

Sadly this was not caught by tests since none of them uses DateTime with WriteEventCore - we are only testing the varargs overload.

The fix here would be to change

runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

Line 1844 in a25aa66

decoded = *(DateTime*)dataPointer;

to

decoded = DateTime.FromFileTimeUtc(*(long*)dataPointer);

[andrew-hampton]

The workaround I proposed also only works for local listeners. If you're sending events to another process, in my experience they're still expecting them to be FileTime ticks. This creates a scenario where you want to keep the same write event behavior as pre-6.0, but then you have to jump through extra hoops to get the correct value if using a local trace listener.

[MJSanfelippo]

I updated ours to be ToBinary() for now, but I'd like to keep them the way they were.

[Samirat]

@MihaZupan Yeah, I agree, it's not really a workaround. As far as I can tell, it results in a completely different telemetry contract, since we're sending a different, not really related number for DateTimes. This workaround only fixes things to jive between the .NET EventSource publishing libraries and listening/decoding libraries, but most people are sending telemetry somewhere else, in which case this is totally breaking.

[MihaZupan]

Note that the serialized value of a DateTime has not changed.
The only thing that changed is how the in-process EventListener decodes this value.

External telemetry systems should not be impacted (unless they are being fed by data coming from EventListener).

[Samirat]

Thanks, @MihaZupan, I was afraid some WriteEvent overloads but not others would be impacted to write ticks instead of FileTime, but if they encode the data the same way as before, we can just fix the EventListener usages (which we use in tests). Looking at the PR some more, it looks like this only affects data being sent to listeners?

[andrew-hampton]

I've updated my original post to remove the known workaround since it's unlikely to result in the correct behavior in most cases. The workaround was that if you're only using a local listener then you can get the same behavior by updating to use dateTime.ToBinary() instead of dateTime.ToFileTimeUtc() however this is unlikely to work when sending telemetry to external systems.