Async thread's Activiy.Current is set incorrectly and cannot be rolled back

[CuteLeon]

Description

Hi Team:
I found that Activity.Current is returning a outdated Activity when start new activity in an async scenario, because Activity.Current's type is AsyncLocal and Activity's Parent is passed to mutilple thread but Activity only stopped on single thread.;

I started the ActivityParent in ThreadParent, then call and await an async task on ThreadChild in ActivityA's scope, create the ActivityChild on ThreadChild, ActivityChild is having ActivityParent as its parent, which is good.
Then I stopped ActivityChild on ThreadChild, ThreadChild's Activity.Current is rolled back to ActivityChild's parent (ActicityParent).
Then program go back to ThreadParent and ActivityParent stops on ThreadParent, ThreadParent's Activity.Current rolls back to ActivityParent's parent (null), which is good.
ThreadChild is designed to be alive and waiting for other jobs, but ActivityParent will never stop again on ThreadChild, so that ThreadChild's Activity.Current keeps returnning outdated ActivityParent as new Activity's parent on ThreadChild, and can not be rolled back to null any more.

Reproduction Steps

static async Task Main(string[] args)
{
    var listener = new ActivityListener
    {
        ShouldListenTo = (x) => true,
        Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllDataAndRecorded,
        ActivityStarted = (x) =>
        {
            Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] ActivityStarted: {x.DisplayName} (Parent={x.Parent?.DisplayName ?? "[null]"}) (Current={Activity.Current?.DisplayName ?? "[null]"})");
        },
        ActivityStopped = (x) =>
        {
            Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] ActivityStopped: {x.DisplayName} (Parent={x.Parent?.DisplayName ?? "[null]"}) (Current={Activity.Current?.DisplayName ?? "[null]"})");
        }
    };
    ActivitySource.AddActivityListener(listener);

    Activity.CurrentChanged += (s, e) =>
    {
        Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] \t\tCurrentChanged: {e.Previous?.DisplayName ?? "[null]"} => {e.Current?.DisplayName ?? "[null]"}");
    };

    var source = new ActivitySource("TestActivitySource");
    Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Current activity before Main: {Activity.Current?.DisplayName ?? "[null]"}");
    using (var activity = source.StartActivity("ActivityParent")!)
    {
        Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Current activity in Main: {Activity.Current?.DisplayName ?? "[null]"}");

        var task = AsyncTask();
        Thread.Sleep(30);
        Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Current activity in Main after async task: {Activity.Current?.DisplayName ?? "[null]"}");
        await task;
    }
    Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Current activity after Main: {Activity.Current?.DisplayName ?? "[null]"}");
    Console.Read();
}

static async Task AsyncTask()
{
    var source = new ActivitySource("TestActivitySource");
    Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Current activity before async task: {Activity.Current?.DisplayName ?? "[null]"}");
    using (var activity = source.StartActivity("ActivityChild")!)
    {
        Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Current activity in async task: {Activity.Current?.DisplayName ?? "[null]"}");
        await Task.Delay(10);
    }
    // Here, ThreadChild's Activity.Current is ActivityParent instead of null, which is bad.
    Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Current activity after async task: {Activity.Current?.DisplayName ?? "[null]"}");
}

Expected behavior

Return an Activity object with correct parent from ActivitySource.StartActivity() in async scenario.

Actual behavior

Activity.Current can not roll back correctly once activitywas passed over multiple threads.

Regression?

No response

Known Workarounds

No response

Configuration

.Net 8.0
Windows Server 2022
x64

Other information

No response

[CuteLeon]

14:05:10.021 [TID=  1] Current activity before Main: [null]
14:05:10.031 [TID=  1]          CurrentChanged: [null] => ActivityParent
14:05:10.031 [TID=  1] ActivityStarted: ActivityParent (Parent=[null]) (Current=ActivityParent)
14:05:10.031 [TID=  1] Current activity in Main: ActivityParent
14:05:10.032 [TID=  1] Current activity before async task: ActivityParent
14:05:10.032 [TID=  1]          CurrentChanged: ActivityParent => ActivityChild
14:05:10.032 [TID=  1] ActivityStarted: ActivityChild (Parent=ActivityParent) (Current=ActivityChild)
14:05:10.032 [TID=  1] Current activity in async task: ActivityChild
14:05:10.047 [TID= 10] ActivityStopped: ActivityChild (Parent=ActivityParent) (Current=ActivityChild)
14:05:10.047 [TID= 10]          CurrentChanged: ActivityChild => ActivityParent
14:05:10.047 [TID= 10] Current activity after async task: ActivityParent
14:05:10.078 [TID=  1] Current activity in Main after async task: ActivityParent
14:05:10.078 [TID=  1] ActivityStopped: ActivityParent (Parent=[null]) (Current=ActivityParent)
14:05:10.078 [TID=  1]          CurrentChanged: ActivityParent => [null]
14:05:10.078 [TID=  1] Current activity after Main: [null]

You can see 14:05:10.047 [TID= 10] Current activity after async task: ActivityParent

[davidfowl]

This is unfortunately by design because of how async locals work. Also this example is inherently racy. What are you trying to achieve?

[tarekgh]

@CuteLeon I am closing the issue as @davidfowl indicated this is by design how the async local work. Feel free to respond with any questions or ask we can help with.

[CuteLeon]

Hi @davidfowl @tarekgh
Thank you for your clarification

My actual scenario is like below:

1. I have 2 forms (FormA, FormB) running message loops in 2 separate STA threads (ThreadA, ThreadB) in the same process due to heavy UI workload. (FormA is the main entry form to manage all other child component forms, FormB is one of child component forms).
2. FormA's async Task Initialize() starts a activity with name "MainInitialization" on ThreadA, and call await formB.Invoke(formB.Initialize) inside.
3. FormB's Initialize() method starts a child activity with name "FormBInitialization" on ThreadB, 'FormBInitialization' is having "MainInitialization" as parent.
4. "FormBInitialization" stops on ThreadB and rollback ThreadB's Activity.Current to be "MainInitialization",
   "MainInitialization" stops on ThreadA and reset ThreadA's Activity.Current as null.
5. If user makes some other operations on FormB's controls and starts new activities in controls' callback methods (On STA ThreadB), these new activities are having "MainInitialization" as parent which is outdated, while null should be expected.

I understand that AsyncLocal can manage independent data in each asynchronous task. But in my scenario, activity "MainInitialization" was propagated to multiple threads/tasks, but only stopped in a single thread/task, which resulted in the inability to correctly roll back the current activity to null in the extra threads/tasks, and it causes new activities starting on extra threads to inherit from the incorrect parent activity.
Is it prohibited to execute asynchronous tasks in an Activity? Or should we adjust the algorithm for Activity's rollback or inheritance logic? Or is there any other solution to ensure that newly opened activities obtain null as the parent.
Looking forward to your reply.

[CuteLeon]

And here is a WinForm application to reproduce:
Execute program and Click on FormB to reproduce.

using System.Diagnostics;
using Microsoft.Extensions.DependencyInjection;

namespace WinFormsApp1
{
    class FormA : Form
    {
        private FormB formB;
        private readonly IServiceProvider provider;
        private readonly ActivitySource activitySource;

        public FormA(IServiceProvider provider, ActivitySource activitySource)
        {
            this.Text = "Form A";
            this.provider = provider;
            this.activitySource = activitySource;
        }

        protected override void OnShown(EventArgs e)
        {
            Debug.Print($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] {this.GetType().Name} Handle created.");
            base.OnShown(e);
            this.Initialize().ConfigureAwait(false);
        }

        public async Task Initialize()
        {
            var mainActivity = this.activitySource.StartActivity("MainActivity");
            var form = default(FormB)!;
            using var waitHandle = new AutoResetEvent(false);
            var threadStart = new ThreadStart(() =>
            {
                form = provider.GetRequiredService<FormB>();
                _ = form.Handle;
                waitHandle.Set();
                form.Show();
                Application.Run(form);
            });
            var thread = new Thread(threadStart);
            thread.SetApartmentState(ApartmentState.STA);
            thread.Start();
            waitHandle.WaitOne();
            this.formB = form;

            await Task.WhenAll(new FormB[] { formB }.Select(x => x.Initialize()));
            await Task.Delay(100);
            mainActivity?.Stop();
        }
    }

    class FormB : Form
    {
        private readonly ActivitySource activitySource;

        public FormB(ActivitySource activitySource)
        {
            this.Text = "Form B";
            this.activitySource = activitySource;
        }

        protected override void OnHandleCreated(EventArgs e)
        {
            Debug.Print($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] {this.GetType().Name} Handle created.");
            base.OnHandleCreated(e);
        }

        public async Task Initialize()
        {
            var childActivity = this.activitySource.StartActivity("ChildActivity");
            await Task.Delay(100);
            Debug.Assert(childActivity?.Parent is not null && childActivity.Parent.DisplayName == "MainActivity");
            childActivity?.Stop();
        }

        protected override void OnClick(EventArgs e)
        {
            Debug.Print($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] Clicked on FormB >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>");
            base.OnClick(e);
            var clickActivity = this.activitySource.StartActivity("ClickActivity");
            // Program is break here if you click on FormB
            Debug.Assert(clickActivity?.Parent is null);
            clickActivity?.Stop();
        }
    }

    internal static class Program
    {
        [STAThread]
        static void Main()
        {
            ApplicationConfiguration.Initialize();

            var services = new ServiceCollection();
            services.AddSingleton<FormA>();
            services.AddSingleton<FormB>();
            services.AddSingleton<ActivitySource>(new ActivitySource("MyActivitySource"));
            services.AddSingleton<ActivityListener>(new ActivityListener
            {
                ShouldListenTo = (x) => true,
                Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllDataAndRecorded,
                ActivityStarted = (x) => Debug.Print($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] ActivityStarted: {x.DisplayName} (Parent={x.Parent?.DisplayName ?? "[null]"}) (Current={Activity.Current?.DisplayName ?? "[null]"})"),
                ActivityStopped = (x) => Debug.Print($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] ActivityStopped: {x.DisplayName} (Parent={x.Parent?.DisplayName ?? "[null]"}) (Current={Activity.Current?.DisplayName ?? "[null]"})"),
            });
            var provider = services.BuildServiceProvider();
            var activitySource = provider.GetRequiredService<ActivitySource>();
            var activityListener = provider.GetRequiredService<ActivityListener>();
            ActivitySource.AddActivityListener(activityListener);
            Activity.CurrentChanged += (s, e) => Debug.Print($"{DateTime.Now:HH:mm:ss.fff} [TID={Environment.CurrentManagedThreadId,3}] \t\tCurrentChanged: {e.Previous?.DisplayName ?? "[null]"} => {e.Current?.DisplayName ?? "[null]"}");

            var formA = provider.GetRequiredService<FormA>();
            Application.Run(formA);
        }
    }
}

[CuteLeon]

And I found that if I move var mainActivity = this.activitySource.StartActivity("MainActivity"); behind waitHandle.WaitOne(); in FormA's Initialize() method, issue was resolved. But I don't understand why.

[tarekgh]

And I found that if I move var mainActivity = this.activitySource.StartActivity("MainActivity"); behind waitHandle.WaitOne(); in FormA's Initialize() method, issue was resolved. But I don't understand why.

If you start the activity before calling Thread.Start call, the execution context will include the created activity, and form B will execute with Activity.Current set to that activity. On the other hand, if you start the activity after Thread.Start, the execution context will not have Activity.Current set when form B initializes on the other thread. In this case, the parent activity of the activity created in the B thread will likely be null.

[tarekgh]

What are you trying to achieve here? Do you want thread B to use the activity created in form A as its parent? Or do you prefer to always have a null parent in form B? Alternatively, do you want the parent to be set only during form B initialization, with any subsequent activity creations having a null parent?

[CuteLeon]

I hope "the parent to be set only during form B initialization, with any subsequent activity creations having a null parent", because form B initialization is inside of form A initialization.
And I think the root cause should be I started FormB's STA thread in FormA's activity and made FormB's thread context captured FormA's activity. I will move thread creations out of main initialization to solve this issue.
Great thanks for your help.

[tarekgh]

If you want to keep your original code, in B initialization after stopping the activity which is created there, you can do Activity.Current = null.
I'll leave it to you to decide the best action you can do with your code.