Bug 24757

Summary: LogicalCallContext not flowing with async calls
Product: [Mono] Class Libraries Reporter: pzavolinsky
Component: mscorlibAssignee: Bugzilla <bugzilla>
Status: RESOLVED FIXED    
Severity: normal CC: masafa, mono-bugs+mono
Priority: ---    
Version: 3.8.0   
Target Milestone: Untriaged   
Hardware: PC   
OS: Linux   
Tags: Is this bug a regression?: ---
Last known good build:
Attachments: Repro code (mcs MonoReproLogicalCallContext.cs; mono MonoReproLogicalCallContext.exe)

Description pzavolinsky 2014-11-23 10:20:29 UTC
Created attachment 8844 [details]
Repro code (mcs MonoReproLogicalCallContext.cs; mono MonoReproLogicalCallContext.exe)

Trying to implement this http://blog.stephencleary.com/2013/04/implicit-async-context-asynclocal.html works in Microsoft .NET but fails in Mono 3.10.0. I'm attaching a simplified repro code.

Essentially the following snippet does not behave as expected (i.e. output "A == A" and "B == B", in any order):
  public static void Main(string[] args)
  {
    Task.WhenAll(Work("A"), Work("B")).Wait();
  }
  public static async Task Work(string name)
  {
    CallContext.LogicalSetData("name", name);
    await Task.Delay(10);
    Console.WriteLine("{0} == {1}", name, CallContext.LogicalGetData("name"));
  }

Output
------
The repro code in Mono 3.1.0 outputs:
A == 
B == 

In Microsoft .NET 4.5 outputs (as expected):
A == A
B == B

Environment
-----------
$ mono --version
Mono JIT compiler version 3.10.0 (tarball Wed Nov  5 12:50:04 UTC 2014)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
        TLS:           __thread
        SIGSEGV:       altstack
        Notifications: epoll
        Architecture:  amd64
        Disabled:      none
        Misc:          softdebug 
        LLVM:          supported, not enabled.
        GC:            sgen

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 12.04.5 LTS
Release:        12.04
Codename:       precise

$ cat /proc/cpuinfo | grep 'model name' | uniq
model name      : Intel(R) Core(TM) i5-3317U CPU @ 1.70GHz

$ dpkg -l | grep mono-mcs
ii  mono-mcs                                                    3.10.0-0xamarin2                                    Mono C# 2.0 / 3.0 / 4.0 / 5.0  compiler for CLI 2.0 / 4.0 / 4.5

Analysis
--------
I did some poking around the code and it looks like the ExecutionContext captured by the System.Threading.Tasks.Task.ctor is not restored previous to the continuation execution (i.e. ExecutionContext.Run is never called). I've check this by building from source and adding Console.WriteLines in the Caputre and Run lines.

Here is the stack trace after the Console.WriteLine in the Work() method:
   at MonoReproLogicalCallContext.MainClass+<Work>c__async0.MoveNext()
   at System.Threading.Tasks.AwaiterActionContinuation.Execute()
   at System.Threading.Tasks.Task.ProcessCompleteDelegates()
   at System.Threading.Tasks.Task.Finish()
   at System.Threading.Tasks.Task.<Delay>m__2(System.Object state)
   at System.Threading.Timer+Scheduler.TimerCB(System.Object o)

After running the sample code many times I had a different (yet still invalid output):
A == A
B ==

The working task (A) produced this stack trace:
   at MonoReproLogicalCallContext.MainClass+<Work>c__async0.MoveNext()
   at System.Threading.Tasks.TaskActionInvoker+ActionInvoke.Invoke(System.Threading.Tasks.Task owner, System.Object state, System.Threading.Tasks.Task context)
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.<ThreadStart>m__1(System.Object l)
   at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state)
   at System.Threading.Tasks.Task.ThreadStart()
   at System.Threading.Tasks.Task.Execute()
   at System.Threading.Tasks.TpScheduler.TaskExecuterCallback(System.Object obj)

In some cases ExecutionContext.Run does get called and everything works as expected, so maybe this an optimization side effect.
Comment 1 Marek Safar 2014-11-26 13:03:55 UTC
Fixed in master