I think I've found at least part of the source of the confusion: there are two seemingly different events that cause the notification to happen with ThreadContextChanged set to true. The first is when the call context switches from one thread to another (or has the opportunity to do so). The second is when the call context winds back up the stack. This can be seen when the following code runs:
private static AsyncLocal<string> _localContextId = new AsyncLocal<string>();
private static AsyncLocal<string> _local = new AsyncLocal<string>(c => System.Diagnostics.Debug.WriteLine($"Thread:{System.Threading.Thread.CurrentThread.ManagedThreadId},Context:{_localContextId.Value ?? Guid.Empty.ToString("N")},Previous:{c.PreviousValue ?? "<null>"},Current:{c.CurrentValue ?? "<null>"},ThreadContextChanged:{c.ThreadContextChanged}"));
[TestMethod]
public async Task AsyncLocalTest1()
{
_localContextId.Value = Guid.NewGuid().ToString("N");
DumpState(1, 0);
await Task.Delay(100);
DumpState(1, 1);
_local.Value = "AsyncLocalTest1";
DumpState(1, 2);
await Task.Delay(100);
DumpState(1, 3);
await AsyncLocalTest2();
DumpState(1, 4);
await Task.Delay(100);
DumpState(1, 5);
}
private async Task AsyncLocalTest2()
{
DumpState(2, 0);
await Task.Delay(100);
DumpState(2, 1);
_local.Value = "AsyncLocalTest2";
DumpState(2, 2);
await Task.Delay(100);
DumpState(2, 3);
await AsyncLocalTest3();
DumpState(2, 4);
await Task.Delay(100);
DumpState(2, 5);
}
private async Task AsyncLocalTest3()
{
DumpState(3, 0);
await Task.Delay(100);
DumpState(3, 1);
_local.Value = "AsyncLocalTest3";
DumpState(3, 2);
await Task.Delay(100);
DumpState(3, 3);
}
private void DumpState(int major, int minor)
{
System.Diagnostics.Debug.WriteLine($"Thread:{System.Threading.Thread.CurrentThread.ManagedThreadId},AsyncLocalTest{major}.{minor}: " + _local.Value ?? "<null>");
}
and produces the following output (this is just a sample--under load there would likely be more threads involved):
Thread:13,AsyncLocalTest1.0:
Thread:9,AsyncLocalTest1.1:
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest1,ThreadContextChanged:False
Thread:9,AsyncLocalTest1.2: AsyncLocalTest1
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest1,Current:<null>,ThreadContextChanged:True
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest1,ThreadContextChanged:True
Thread:9,AsyncLocalTest1.3: AsyncLocalTest1
Thread:9,AsyncLocalTest2.0: AsyncLocalTest1
Thread:9,Context:00000000000000000000000000000000,Previous:AsyncLocalTest1,Current:<null>,ThreadContextChanged:True
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest1,ThreadContextChanged:True
Thread:9,AsyncLocalTest2.1: AsyncLocalTest1
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest1,Current:AsyncLocalTest2,ThreadContextChanged:False
Thread:9,AsyncLocalTest2.2: AsyncLocalTest2
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest2,Current:AsyncLocalTest1,ThreadContextChanged:True
Thread:9,Context:00000000000000000000000000000000,Previous:AsyncLocalTest1,Current:<null>,ThreadContextChanged:True
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest2,ThreadContextChanged:True
Thread:9,AsyncLocalTest2.3: AsyncLocalTest2
Thread:9,AsyncLocalTest3.0: AsyncLocalTest2
Thread:9,Context:00000000000000000000000000000000,Previous:AsyncLocalTest2,Current:<null>,ThreadContextChanged:True
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest2,ThreadContextChanged:True
Thread:9,AsyncLocalTest3.1: AsyncLocalTest2
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest2,Current:AsyncLocalTest3,ThreadContextChanged:False
Thread:9,AsyncLocalTest3.2: AsyncLocalTest3
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest3,Current:AsyncLocalTest2,ThreadContextChanged:True
Thread:9,Context:00000000000000000000000000000000,Previous:AsyncLocalTest2,Current:<null>,ThreadContextChanged:True
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest3,ThreadContextChanged:True
Thread:9,AsyncLocalTest3.3: AsyncLocalTest3
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest3,Current:AsyncLocalTest2,ThreadContextChanged:True
Thread:9,AsyncLocalTest2.4: AsyncLocalTest2
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest2,Current:AsyncLocalTest3,ThreadContextChanged:True
Thread:9,Context:00000000000000000000000000000000,Previous:AsyncLocalTest3,Current:<null>,ThreadContextChanged:True
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest2,ThreadContextChanged:True
Thread:9,AsyncLocalTest2.5: AsyncLocalTest2
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest2,Current:AsyncLocalTest1,ThreadContextChanged:True
Thread:9,AsyncLocalTest1.4: AsyncLocalTest1
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:AsyncLocalTest1,Current:AsyncLocalTest2,ThreadContextChanged:True
Thread:9,Context:00000000000000000000000000000000,Previous:AsyncLocalTest2,Current:<null>,ThreadContextChanged:True
Thread:9,Context:002d421118804fb3b6f40941df50e056,Previous:<null>,Current:AsyncLocalTest1,ThreadContextChanged:True
Thread:9,AsyncLocalTest1.5: AsyncLocalTest1
Thread:9,Context:00000000000000000000000000000000,Previous:AsyncLocalTest1,Current:<null>,ThreadContextChanged:True
It appears that two calls happen every time the call context is interrupted, first changing the value to null and then changing it back (which could happen on another thread, but not necessarily). I would presume that the first is when the call context and the thread are disassociated and the seconds is when they are reassociated. When the stack unwinds, there is an additional call that changes the value for that.