Why does NLog.ILogger.Debug dead lock when called from an async function in a nested class during in-CodePudding

This is the minimum (and simplified) repro of the real code that I was investigating due to it causing a dead lock. The OuterClass has some nested classes, which get initialize (and load some data) with initialization of the outer class. It's important that the data is available once the object is initialized.

public class OuterClass
{   
    static ILogger Log = LogManager.GetLogger("OuterClass");

    private static InnerClass _innerClass;
    public static OuterClass Instance { get; private set; }

    private OuterClass()
    {
        Log.Debug("Constructor called");
        _innerClass = new InnerClass();
    }

    static OuterClass()
    {
        Instance = new OuterClass();
    }

    public class InnerClass
    {
        // using it's own logger, it will not dead lock
        //static ILogger Log = LogManager.GetLogger("InnerClass");

        private String _data;
        public InnerClass()
        {
            LoadOrUpdateDataAsync().Wait(); // will make the second Log.Debug call dead lock
            //_ = LoadOrUpdateDataAsync(); // will work
        }

        public async Task LoadOrUpdateDataAsync()
        {
            Log.Debug("This works");

            _data = await DataClass.GetDataAsync("https://someusefulapi.com/api/xyz");

            Log.Debug("If you see this, it did not block"); // this line blocks
        }
    }
}

public static class DataClass
{
    static ILogger Log = LogManager.GetLogger("DataClass");
    public static async Task<string> GetDataAsync(string uri)
    {
        // just example code, HttpClient should not be in a using block
        using (var client = new HttpClient())
        {
            var data = await client.GetStringAsync(uri);
            Log.Debug("Data loaded from {0}", uri);
            return data;
        }
    }
}

Console output from above code:

Time         Logger  Thread-Id   Message
16:47:39 OuterClass          1   Constructor called
16:47:39 OuterClass          1   This works
16:47:40  DataClass          7   Data loaded from https://someusefulapi.com/api/xyz

The second Log Log.Debug("If you see this..."); blocks - the application hangs. I am guessing that it hangs at this point, because the LoadOrUpdateDataAsync().Wait(); call is blocking the Logger which is shared by the OuterClass and InnerClass. The await DataClass.GetDataAsync(...) is executed by a different thread (different thread id). So when the await completes, the method resumes on the "new" thread, but the Logger is blocked by the main thread. Or should the code actually work, meaning it's an NLog issue?

The NLog configuration is minimalistic. I tried versions NLog 4.7.15 and 5.0.4 - which behave identical. The async="true" option, also makes no difference. It's .Net Framework 4.7.2.

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

    <targets async="true">
        <target name="console" xsi:type="ColoredConsole" layout="${date:format=HH\:mm\:ss} ${pad:padCharacter= :padding=10:fixedLength=True:inner=${logger}} ${mdlc:item=ProcessDescriptorId}   ${threadid}   ${message} ${exception:format=tostring} ${exception:format=stacktrace}" />
    </targets>
    <rules>
        <logger name="*" minlevel="Debug" writeTo="console" />
    </rules>
</nlog>

This code really only hangs when LoadOrUpdateDataAsync() is called from the constructor. Putting the call to an Init()function and calling it with OuterClass.Instance.Init(); will not block.

Also, using the discard operator _ = LoadOrUpdateDataAsync(); will work. But it's not an option, because the main Thread will continue, without having the confidence that the data is really loaded.

Console output with _ = LoadOrUpdateDataAsync();:

Time         Logger    Thread-Id   Message
16:49:54 OuterClass            1   Constructor called
16:49:54 OuterClass            1   This works
16:49:55  DataClass            9   Data loaded from https://someusefulapi.com/api/xyz
16:49:55 OuterClass            9   If you see this, it did not block

Also using an own Logger in the InnerClass will work (with the .Wait() call).

Console output with own Logger in InnerClass and LoadOrUpdateDataAsync().Wait();:

Time         Logger    Thread-Id   Message
16:52:51 OuterClass            1   Constructor called
16:52:51 InnerClass            1   This works
16:52:52  DataClass            8   Data loaded from https://someusefulapi.com/api/xyz
16:52:52 InnerClass            8   If you see this, it did not block

From the 2 last examples it is clear that the second Log.Debug() runs on a different thread than the first one.

I am aware that calling async functions from constructors is suboptimal and that there are better ways to do it - like using the Factory Pattern as described in this blog by Stephen Cleary

I am primarilly interested in why this codes blocks and wish to understand what is technically going on here. Are my assumptions correct or am I on the wrong path?

Second, is the above mentioned Factory Pattern the "correct" way to solve it, or is there an even better approach?

CodePudding user response：

I can't prove it cause this will require going down the rabbit hole of CLR implementation (playing with dotnet-dump analyze seems to result in the unmanaged transition in the continuation invocation after _data = await ...) but the reason for such behaviour is not the NLog per se but the fact that runtime guarantees that static constructor will be executed only once and in your code basically the following happens:

OuterClass static ctor starts invocation
InnerClass ctor is called
InnerClass ctor blocks on LoadOrUpdateDataAsync (and blocks the thread which handles the ctor)
LoadOrUpdateDataAsync waits for IO completion
After IO completion LoadOrUpdateDataAsync tries to access something from OuterClass from another thread but OuterClass static construction has not finished, so it blocks until the construction is finished leading to deadlock cause static ctor waits for LoadOrUpdateDataAsync.

The repro can be simplified to:

public class OuterClass
{   
    // ...

    public static void DoSomething()
    {
        Console.WriteLine("Here Outer");
    }

    public class InnerClass
    {
        private String _data;
        public InnerClass()
        {
            LoadOrUpdateDataAsync().GetAwaiter().GetResult();//.Wait();
        }

        public async Task LoadOrUpdateDataAsync()
        {
            _data = await DataClass.GetDataAsync("https://api.coindesk.com/v1/bpi/currentprice.json").ConfigureAwait(false);
            Console.WriteLine("Here Inner"); // works
            OuterClass.DoSomething(); // blocks
        }
    }
}

This actually is described in the docs:

The runtime calls a static constructor no more than once in a single application domain. That call is made in a locked region based on the specific type of the class. No additional locking mechanisms are needed in the body of a static constructor. To avoid the risk of deadlocks, don't block the current thread in static constructors and initializers. For example, don't wait on tasks, threads, wait handles or events, don't acquire locks, and don't execute blocking parallel operations such as parallel loops, Parallel.Invoke and Parallel LINQ queries.