EventSource EventWrittenEventArgs.ActivityId isn't always set

[MihaZupan]

I ran into this while working on tests for #41670.

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

Lines 4544 to 4557 in abeadc2

	public Guid ActivityId
	{
	get
	{
	Guid activityId = m_activityId;
	if (activityId == Guid.Empty)
	{
	activityId = EventSource.CurrentThreadActivityId;
	}
	return activityId;
	}
	internal set => m_activityId = value;
	}

The ActivityId property will return the m_activityId field if set (Start/Stop events).
If it wasn't set, it will fetch the current thread's activity id - but it won't save it.

This means that the behavior is correct when the EventArgs are analyzed in the event callback itself.
If the EventArgs are stored and looked at later, ActivityId info is lost (it'll always return Zero).

Considering that the property is described as Activity ID for the thread on which the event was written, this seems like a bug and not intentional behavior (which is also incredibly confusing to debug).

Is there a significant perf drawback to the approach of simply always fetching EventSource.CurrentThreadActivityId when creating the EventArgs and removing the getter logic?

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

[tarekgh]

CC @noahfalk who can address this issue.

[tommcdon]

adding @sywhang @josalem. It sounds like we should document this behavior for 5.0 and try to address it in 6.0.

[josalem]

This means that the behavior is correct when the EventArgs are analyzed in the event callback itself.
If the EventArgs are stored and looked at later, ActivityId info is lost (it'll always return Zero).

How are you consuming these events? Are you listening to these events live via an EventListener or are you using EventPipe to collect these events and save them to a file?

[MihaZupan]

The use case here is using TestEventListener during tests, and saving events to a ConcurrentQueue.
After the tested code runs, EventArgs are analyzed (including comparing ActivityIds).

I modified the TestEventListener to allow subscribing to multiple event sources (including TplEventSource to track activities in tests) - I will ping you on the PR.

using var listener = new TestEventListener("System.Net.Sockets", EventLevel.Verbose, 0.1);
listener.AddActivityTracking(); // Doesn't exist on current TestEventListener

var events = new ConcurrentQueue<EventWrittenEventArgs>();
await listener.RunWithCallbackAsync(events.Enqueue, async () =>
{
    // Stuff that triggers events
}

EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "FooStart");
EventWrittenEventArgs something = Assert.Single(events, e => e.EventName == "FooSomething");
EventWrittenEventArgs stop = Assert.Single(events, e => e.EventName == "FooStop");

Assert.NotEqual(Guid.Empty, start.ActivityId);
Assert.Equal(start.ActivityId, something.ActivityId); // Fail
Assert.Equal(start.ActivityId, stop.ActivityId);

Here, ActivityId would be set correctly for FooStart/FooStop, but Guid.Empty for FooSomething.

If instead you look at the EventArgs inside the RunWithCallbackAsync callback, it will be correct (as you're still on the Thread that logged the event).

listener.RunWithCallbackAsync(e => { Console.WriteLine(e.ActivityId); events.Enqueue(e); }, ...

[josalem]

I'm not sure if there is an explicit reason for this behavior (the code hasn't changed in ~1 year), but I agree with Tom on how we should handle this (document now; address/change in 6.0). For now, would it be sufficient for the test to store a tuple (Guid, EventWrittenEventArgs) in the queue and just fetch the Activity ID in the callback directly?

[MihaZupan]

Yes a temporary fix would be changing the test / adding 2 lines of reflection into TestEventListener to set the private field.