log4net LogicalThreadContext not working

Question

I have what is either a bug in log4net, or a misunderstanding on my part.

I'm trying to use LogicalThreadContext to associate some data with a call context and have it propagate to any log statements made by any thread in that context. That is the purported advantage of LogicalThreadContext over ThreadContext.

I wasn't able to get the propagation to work, so I put together a simple unit test to see whether it would work, and it doesn't. Here it is:

[Fact]
public void log4net_logical_thread_context_test()
{
    XmlConfigurator.Configure();
    var log = LogManager.GetLogger(GetType());
    var waitHandle = new ManualResetEvent(false);

    using (LogicalThreadContext.Stacks["foo"].Push("Some contextual info"))
    {
        log.Debug("START");

        ThreadPool.QueueUserWorkItem(delegate
        {
            log.Debug("A DIFFERENT THREAD");
            waitHandle.Set();
        });

        waitHandle.WaitOne();
        log.Debug("STOP");
    }
}

My log4net configuration looks like this:

<?xml version="1.0" encoding="utf-8" ?>

<configuration>
    <configSections>
        <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
    </configSections>

    <log4net>
        <appender name="FileAppender" type="log4net.Appender.FileAppender">
            <file value="log.txt" />
            <appendToFile value="true" />
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="[%thread]|[%property{foo}]|%message%newline"/>
            </layout>
        </appender>

        <root>
            <level value="DEBUG" />
            <appender-ref ref="FileAppender" />
        </root>
    </log4net>
</configuration>

And my output looks like this:

[xUnit.net STA Test Execution Thread]|[Some contextual info]|START
[32]|[(null)]|A DIFFERENT THREAD
[xUnit.net STA Test Execution Thread]|[Some contextual info]|STOP

As you can see, the data I push onto the LTC stack is only present in the logging statements made on the same thread. The log statement made by the background thread is lacking the contextual data. Debugging through the test I could see that, indeed, that LogicalThreadContext.Stacks.Count is zero on the background thread.

Digging into the log4net source, I found it utilizing the CallContext class. This class does what it says on the tin - it allows context for the current "call" to be stored and retrieved. How it does this at a low level, I have no idea.

CallContext has two sets of methods with which context information can be stored and retrieved: GetData/SetData and LogicalGetData/LogicalSetData. The documentation is very light on details regarding the difference between these two sets of methods, but the examples use GetData/SetData. And so does log4net's LogicalThreadContext.

A quick test showed that GetData/SetData exhibits the same problem - data does not propagate across threads. I thought I'd give LogicalGetData/LogicalSetData a go instead:

[Fact]
public void call_context_test()
{
    XmlConfigurator.Configure();
    var log = LogManager.GetLogger(GetType());

    var count = 5;
    var waitHandles = new ManualResetEvent[count];

    for (var i = 0; i < count; ++i)
    {
        waitHandles[i] = new ManualResetEvent(false);
        var localI = i;

        // on a bg thread, set some call context data
        ThreadPool.QueueUserWorkItem(delegate
        {
            CallContext.LogicalSetData("name", "value " + localI);
            log.DebugFormat("Set call context data to '{0}'", CallContext.LogicalGetData("name"));
            var localWaitHandle = new ManualResetEvent(false);

            // then on another bg thread, make sure the logical call context value is correct with respect to the "owning" bg thread
            ThreadPool.QueueUserWorkItem(delegate
            {
                var value = CallContext.LogicalGetData("name");
                log.DebugFormat("Retrieved call context data '{0}'", value);
                Assert.Equal("value " + localI, value);
                localWaitHandle.Set();
            });

            localWaitHandle.WaitOne();
            waitHandles[localI].Set();
        });
    }

    foreach (var waitHandle in waitHandles)
    {
        waitHandle.WaitOne();
    }
}

This test passes - contextual information is successfully propagated across threads when using LogicalGetData/LogicalSetData.

So my question is this: has log4net gotten this wrong? Or is there something I'm missing?

UPDATE: I also tried doing a custom build of log4net with its LogicalThreadContextProperties class altered as per my findings above. I re-ran my initial test and it worked. This just strikes me as too obvious a problem for a product used by so many people, so I have to assume I'm missing something.

Answer 1

Here is a question that I asked some time back about what the difference is between ThreadContext and LogicalThreadContext:

What is the difference between log4net.ThreadContext and log4net.LogicalThreadContext?

There is a link in there to a posting by Nicko Cadell, one of the log4net authors, about how the LogicalThreadContext works. He talks about items stored in the CallContext that support ILogicalThreadAffinative being automatically propagated to child threads but that log4net does not use ILogicalThreadAffinative. He does not mention anything about using CallContext.LogicalSetData, which, as you have found, causes CallContext data to be propagated to child threads automatically without having to implement ILogicalThreadAffinative.

In conclusion, I don't think that you are missing anything. I do think that log4net has gotten it wrong.

I realize that you did not ask for any code, but here is some work that I did some months ago when I was looking into log4net, CallContext, PatternLayoutConverter, etc.

First, a "logical thread context" object that I threw together several months ago. I wrote it to mimic the logging context abstractions provided by the Castle logging facility.

  public static class LogicalThreadDiagnosticContext
  {
    const string slot = "Logging.Context.LogicalThreadDiagnosticContext";

    internal static IDictionary<string, object> LogicalThreadDictionary
    {
      get
      {
        IDictionary<string, object> dict = (IDictionary<string, object>)CallContext.LogicalGetData(slot);
        if (dict == null)
        {
          dict = new Dictionary<string, object>();
          CallContext.LogicalSetData(slot, dict);
        }

        return dict;
      }
    }

    public new static string ToString()
    {
      if (LogicalThreadDictionary.Count == 0) return "";

      IEnumerable<string> es = (from kvp in LogicalThreadDictionary select string.Format("{0} = {1}", kvp.Key, kvp.Value));

      string s = string.Join(";", es);

      return s;
    }

    public static IDictionary<string, object> CloneProperties()
    {
      return new Dictionary<string, object>(LogicalThreadDictionary);
    }

    public static void Set(string item, object value)
    {
      LogicalThreadDictionary[item] = value;
    }

    public static object Get(string item)
    {
      object s;

      if (!LogicalThreadDictionary.TryGetValue(item, out s))
      {
        s = string.Empty;
      }

      return s;
    }

    public static bool Contains(string item)
    {
      return LogicalThreadDictionary.ContainsKey(item);
    }

    public static void Remove(string item)
    {
      LogicalThreadDictionary.Remove(item);
    }

    public static void Clear()
    {
      LogicalThreadDictionary.Clear();
    }

    public static int Count
    {
      get { return LogicalThreadDictionary.Count; }
    }
  }

Here is a log4net PatternLayoutConverter (that was written at a different time, primarily as an experiment to help learn about log4net and the CallContext). It expects the Option property to specify a particular named value from the logical call context. It would not be too hard to write a similar PatternLayoutConverter that got the dictionary from the logical context based on the name above, and then used the Option parameter to index into the dictionary.

  class LogicalCallContextLayoutConverter : PatternLayoutConverter
  {
    private bool isDisabled = false;

    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      if (isDisabled || Option == null || Option.Length == 0) return;

      try
      {
        object data = CallContext.LogicalGetData(Option);
        if (data != null)
        {
          writer.Write(data.ToString());
        }
      }
      catch (SecurityException)
      {
        isDisabled = true;
      }
    }
  }

To use the dictionary scheme as in the first code sample, the PatternLayoutConverter might look something like this (uncompiled and untested):

  class LogicalCallContextLayoutConverter : PatternLayoutConverter
  {
    private bool isDisabled = false;

    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      if (isDisabled || Option == null || Option.Length == 0) return;

      try
      {
        object data = LogicalThreadDiagnosticContext[Option];
        if (data != null)
        {
          if (data != null)
          {
            writer.Write(data.ToString());
          }
        }
      }
      catch (SecurityException)
      {
        isDisabled = true;
      }
    }
  }

Good luck!