Log4net LogicalThreadContext not working as expected

Question

I've been trying to use Log4nets LogicalThreadContext to provide context to each of my log entries. My application uses async/await quite heavily, but from reading various articles the LogicalThreadContext should work properly with asynchronous code, from .NET 4.5 onwards. I'm using .NET 4.5.1 and log4net 2.0.3

I came across a great article by Stephen Cleary about logging and the .NET CallContext, and as a result I decided to take his code and adapt it to use log4net, in an attempt to see if there was something wrong in my code that may have been causing the issue.

Firstly, I ran Stephens code exactly as is and got the expected output like so

Main 1: <SomeWork>
Main 1 A: <MoreWork>
Main 2: <SomeWork>
Main 2 A: <MoreWork>
Main 1 A: </MoreWork>
Main 1 B: <MoreWork>
Main 2 A: </MoreWork>
Main 2 B: <MoreWork>
Main 2 B: </MoreWork>
Main 2: </SomeWork>
Main 1 B: </MoreWork>
Main 1: </SomeWork>

Next, I modified the code to use log4net rather than Stephens custom MyStack

internal class Program
{
    private static readonly ILog Log = LogManager.GetLogger(typeof(Program));
    private const string StackName = "test";

    private static void Main(string[] args)
    {
        XmlConfigurator.Configure();

        using (LogicalThreadContext.Stacks[StackName].Push("Main"))
        {
            Task.WhenAll(SomeWork("1"), SomeWork("2")).Wait();
        }

        Console.ReadKey();
    }

    private static async Task SomeWork(string stackName)
    {
        using (LogicalThreadContext.Stacks[StackName].Push(stackName))
        {
            Log.Info("<SomeWork>");
            await MoreWork("A");
            await MoreWork("B");
            Log.Info("</SomeWork>");
        }
    }

    private static async Task MoreWork(string stackName)
    {
        using (LogicalThreadContext.Stacks[StackName].Push(stackName))
        {
            Log.Info("<MoreWork>");
            await Task.Delay(10);
            Log.Info("</MoreWork>");
        }
    }
}

I expected to get a similar output as before, but instead this time I got the following

Main 1: <SomeWork>
Main 1 A: <MoreWork>
Main 1 A 2: <SomeWork>
Main 1 A 2 A: <MoreWork>
Main 1 A 2 A: </MoreWork>
Main 1 B: <MoreWork>
Main 1 B: </MoreWork>
Main 1 B B: <MoreWork>
Main 1 B B: </MoreWork>
Main 1 B: </MoreWork>
Main 1: </SomeWork>
Main 1: </SomeWork>

Notice the separate logical thread contexts start to overlap. This indicates to me the log4net isn't using the CallContext correctly but from everything I can find it looks like they've already fixed any issues around this.

Has anyone else encountered this or know why this might be happening?

Answer 1

Unfortunately, it looks like log4net still does not work with async logical stacks.

The log4net NuGet package 2.0.3 is log4net 1.2.13 (the current version as of today). There was a bug reported (LOG4NET-317) because at that time LogicalThreadContext used CallContext instead of LogicalCallContext.

The current version of LogicalThreadContext does use LogicalThreadContext, but the current version of ThreadContextStacks does not correctly use an immutable stack.

Interestingly, Andrew Arnott correctly pointed out in the original bug report that they had to use an immutable stack. In 2011.

Feel free to write up a minimal repro and report it as a log4net bug. The key scenario is using the stack within multiple tasks that are combined using Task.WhenAll.

Answer 2

I just ran into this on one of our projects. This should fix it: https://github.com/apache/log4net/pull/12.

The code basically obeys to the shallow-copy-on-write and immutable rules described by @StephenCleary and the accompanied test case withstands the Task.WhenAll scenario.