Debugging an app using TplEventSource keyword 0x80 generates spurious ActivityIDs.

[noahfalk]

Description

The following sample program exercises EventSource and EventListener logging with Activity IDs. Copy and build it in a new Visual Studio .Net Core console app project.

using System;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Threading.Tasks;

namespace ConsoleApp28
{
    class Program
    {
        static MyEventSource log = new MyEventSource();

        static void Main(string[] args)
        {
            
            SimpleEventListener d = new SimpleEventListener();
            Console.WriteLine("{0,-6} {1,-36} {2,-36} {3,-12} {4}", "TID", "ActivityId", "RelatedActivityId", "EventName", "Message");

            log.ThingyStart("begin");
            DoAsyncThings().Wait();
            log.ThingyStop("end");
        }

        static async Task DoAsyncThings()
        {
            await DoThingA();
            await DoThingB();
        }

        static async Task DoThingA()
        {
            log.ThingyStart("Starting a");
            await Task.Delay(100);
            log.Log("I did something in A!");
            log.ThingyStop("Stopping a");
        }
        static async Task DoThingB()
        {
            log.ThingyStart("Starting b");
            await Task.Delay(100);
            log.Log("I did something in B!");
            log.ThingyStop("Stopping b");
        }
    }

    [EventSource(Name ="MyEventSource")]
    class MyEventSource : EventSource
    {
        [Event(1)]
        public void Log(string message)
        {
            WriteEvent(1, message);
        }

        [Event(2, ActivityOptions = EventActivityOptions.Recursive)]
        public void ThingyStart(string message)
        {
            WriteEvent(2, message);
        }

        [Event(3, ActivityOptions = EventActivityOptions.Recursive)]
        public void ThingyStop(string message)
        {
            WriteEvent(3, message);
        }
    }

    class SimpleEventListener : EventListener
    {
        protected override void OnEventSourceCreated(EventSource eventSource)
        {
            if(eventSource.Name == "System.Threading.Tasks.TplEventSource")
            {
                EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)0x80);
            }
            else if(eventSource.Name == "MyEventSource")
            {
                EnableEvents(eventSource, EventLevel.Informational);
            }
        }

        protected override void OnEventWritten(EventWrittenEventArgs eventData)
        {
            string message = "";
            int index = eventData.PayloadNames.IndexOf("message");
            if(index != -1)
            {
                message = (string)eventData.Payload[index];
            }
            Console.WriteLine("{0,-6} {1,-36} {2,-36} {3,-12} {4}", eventData.OSThreadId, eventData.ActivityId, eventData.RelatedActivityId, eventData.EventName, message);
        }
    }
}

2. Run it using CTRL-F5 to avoid using the debugger and note the output. For example:

TID    ActivityId                           RelatedActivityId                    EventName    Message
39416  00000011-0000-0000-0000-0000ea039d59 00000000-0000-0000-0000-000000000000 ThingyStart  begin
39416  00001011-0000-0000-0000-0000ea339d59 00000011-0000-0000-0000-0000ea039d59 ThingyStart  Starting a
39152  00001011-0000-0000-0000-0000ea339d59 00000000-0000-0000-0000-000000000000 Log          I did something in A!
39152  00001011-0000-0000-0000-0000ea339d59 00000000-0000-0000-0000-000000000000 ThingyStop   Stopping a
39152  00002011-0000-0000-0000-0000ea239d59 00000011-0000-0000-0000-0000ea039d59 ThingyStart  Starting b
39152  00002011-0000-0000-0000-0000ea239d59 00000000-0000-0000-0000-000000000000 Log          I did something in B!
39152  00002011-0000-0000-0000-0000ea239d59 00000000-0000-0000-0000-000000000000 ThingyStop   Stopping b
39416  00000011-0000-0000-0000-0000ea039d59 00000000-0000-0000-0000-000000000000 ThingyStop   end

Notice that each GUID in the RelatedActivityId column matches the first row GUID in the ActivityId column. This is correct behavior indicating that the child activities are parented to the root activity.

3. Now run the app again using F5 so that the debugger will be activated and note the output again. For example:

TID    ActivityId                           RelatedActivityId                    EventName    Message
11720  00000011-0000-0000-0000-00000ac99d59 00000000-0000-0000-0000-000000000000 ThingyStart  begin
11720  00001011-0000-0000-0000-00000af99d59 00000011-0000-0000-0000-00000ac99d59 ThingyStart  Starting a
24580  00001011-0000-0000-0000-00000af99d59 00000000-0000-0000-0000-000000000000 Log          I did something in A!
24580  00001011-0000-0000-0000-00000af99d59 00000000-0000-0000-0000-000000000000 ThingyStop   Stopping a
24580  00002011-0000-0000-0000-00000ae99d59 00000002-0001-0000-b450-0000ffdcd7b5 ThingyStart  Starting b
24580  00002011-0000-0000-0000-00000ae99d59 00000000-0000-0000-0000-000000000000 Log          I did something in B!
24580  00002011-0000-0000-0000-00000ae99d59 00000000-0000-0000-0000-000000000000 ThingyStop   Stopping b
11720  00000011-0000-0000-0000-00000ac99d59 00000000-0000-0000-0000-000000000000 ThingyStop   end

Expected behavior: Debug output should also have RelatedActivityIds that match the root activity
Actual behavior: In row 5 the RelatedActivityId will be a novel GUID not seen anywhere else.

For a monitoring system (or human) trying to do activity correlation this novel id prevents parent-child relationships from being inferred.

Configuration

I reproed on Windows x64 .Net Core 3.1.3 but I wouldn't be surprised if the bug reproes across many versions/OS/arch combinations

Regression?

Unsure, but probably not

Other information

I partially debugged the issue and observed that both TplEventSource keyword 'TaskSetActivityIds' (0x10000) and keyword 'TasksFlowActivityIds' (0x80) were enabled. The source indicates these two keywords are supposed to be mutually exclusive but code review on the implementation suggests the invariant isn't fully enforced. In any single pass of OnEventCommand only one keyword or the other can be turned on, but with two separate concurrent sessions each session can turn on one of them without ever disabling the other. This repro scenario probably creates exactly that two session setup.

It wouldn't be hard to enforce the mutual exclusion more strongly in the code but that could have follow on issues where whichever session doesn't get the activity id logging it requested has new failures.

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
Notify danmosemsft if you want to be subscribed.

[noahfalk]

Any change in behavior here is probably a (minor) breaking change. I don't think we'd want to change it at this point in the release.

[josalem]

Agreed.