Rich payload DateTime values get shifted

[christian-clausen]

We have noticed that rich payloads containing DateTime get shifted, so consumed DateTime payload items are different from produced DateTimes. This does not happen for payloads produced by a sub-class of EventSource.

I have attached a full repro that demonstrates the issue: 05_DateTimeRepro.cs.txt

Here follows the part that generates events:

    DateEventSource.Log.EventSourceEvent(NOW);

    var log = new EventSource(TRACELOG_PROVIDER_NAME);
    log.Write(TRACELOG_EVENT_NAME,
        new
        {
            DateNow = NOW,
            Nested = new
            {
                NestedDateNow = NOW
            }
        }
    );

Here follows the output where I have marked the hour shifting that occurs with red boxes:

Coincidence or not, the time is shifted by two hours, and our time zone offset is +2:00, so it somehow seems the offset has been applied one time too much:

• NOW = 13:46 (with offset +02:00)
• UTC corresponding to this is 11:46
• Rich payload values are 15:46 (with offset +02:00).

Is this an error in TraceEvent or EventSource or ...?

[pharring]

Agreed. The serialization code for DateTime (https://github.com/dotnet/corefx/blob/cbc9701436853421b389e118e410e7470c887353/src/Common/src/CoreLib/System/Diagnostics/Tracing/TraceLogging/SimpleTypeInfos.cs#L188) assumes the input is UTC and just serializes Ticks.

I don't know if that can be changed without breaking existing applications.

Workaround: Make sure to use UTC everywhere. In your repro, either use NOW = DateTime.UtcNow instead of NOW = DateTime.Now or convert to UTC when writing the payload:

log.Write(TRACELOG_EVENT_NAME,
    new
    {
        DateNow = NOW.ToUniversalTime(),
        Nested = new
        {
            NestedDateNow = NOW.ToUniversalTime()
            }
        }
     );

[christian-clausen]

Thanks for your quick response and the work-around! I hope you find the courage to fix:-)

[brianrob]

I need to think about this a bit more - I want to say I tried to fix this a while back and was convinced by @vancem that I shouldn't. I'll see if I can dig some context up on this. I could also be lying...

[github-actions[bot]]

Due to lack of recent activity, this issue has been labeled as 'stale'. It will be closed if no further activity occurs within 30 more days. Any new comment will remove the label.

[github-actions[bot]]

This issue will now be closed since it has been labeled 'stale' without activity for 30 days.