How to log correct context with Threadpool threads using log4net?

Question

I am trying to find a way to log useful context from a bunch of threads. The problem is that a lot of code is dealt with on Events that are arriving via threadpool threads (as far as I can tell) so their names are not in relation to any context. The problem can be demonstrated with the following code:

class Program
{
    private static readonly log4net.ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
    static void Main(string[] args)
    {
        new Thread(TestThis).Start("ThreadA");
        new Thread(TestThis).Start("ThreadB");
        Console.ReadLine();
    }

    private static void TestThis(object name)
    {
        var nameStr = (string)name;
        Thread.CurrentThread.Name = nameStr;
        log4net.ThreadContext.Properties["ThreadContext"] = nameStr;
        log4net.LogicalThreadContext.Properties["LogicalThreadContext"] = nameStr;
        log.Debug("From Thread itself");
        ThreadPool.QueueUserWorkItem(x => log.Debug("From threadpool Thread: " + nameStr));
    }
}

The Conversion pattern is:

%date [%thread] %-5level %logger [%property] - %message%newline

The output is like so:

2010-05-21 15:08:02,357 [ThreadA] DEBUG LogicalContextTest.Program [{LogicalThreadContext=ThreadA, log4net:HostName=xxx, ThreadContext=ThreadA}] - From Thread itself
2010-05-21 15:08:02,357 [ThreadB] DEBUG LogicalContextTest.Program [{LogicalThreadContext=ThreadB, log4net:HostName=xxx, ThreadContext=ThreadB}] - From Thread itself
2010-05-21 15:08:02,404 [7] DEBUG LogicalContextTest.Program [{log4net:HostName=xxx}] - From threadpool Thread: ThreadA
2010-05-21 15:08:02,420 [16] DEBUG LogicalContextTest.Program [{log4net:HostName=xxx}] - From threadpool Thread: ThreadB

As you can see the last two rows have no Names of useful information to distinguish the 2 threads, other than manually adding the name to the message (which I want to avoid). How can I get the Name/Context into the log for the threadpool threads without adding it to the message at every call or needing to set the property again in every callback.

Answer 1

UPDATE: 12/11/2014 - See the first part of my post here:

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

for a recent update. Log4Net's LogicalThreadContext has been updated somewhat recently (in the last couple of years) so that it works correctly now. The updated in the linked post gives some details.

END UPDATE.

Here is an idea that might help you. Part of the problem is that the log4net context objects (ThreadContext and LogicalThreadContext) do not "flow" their properties to "child" threads. LogicalThreadContext gives the false impression that it does, but it doesn't. Internally it uses CallContext.SetData to store its properties. Data set via SetData is attached TO THE THREAD, but it is NOT "inherited" by child threads. So, if you set a property via like this:

log4net.LogicalThreadContext.Properties["myprop"] = "abc";

That property will be loggable via the %property pattern converter and will contain a value when logging from the same thread where you set the property in the first place, but it will not contain a value in any child threads that are spawned from that thread.

If you could save your properties via CallContext.LogicalSetData (see link above), then the properties are "flowed" to (or inherited by) any child threads. So, if you could do something like this:

CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);

Then "MyLogicalData" will be available in the thread where you set it as well as in any child threads.

See this blog posting by Jeffrey Richter for more info on using CallContext.LogicalSetData.

You can easily store your own information via CallContext.LogicalSetData AND have it available for logging by log4net by writing your own PatternLayoutConverter. I have attached some sample code for two new PatternLayoutConverters.

The first one allows you to log information stored in the Trace.CorrelationManager's LogicalOperationStack. The layout converter allows you to log the top of the LogicalOperationStack or the entire LogicalOperationStack.

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;

using log4net;
using log4net.Util;
using log4net.Layout.Pattern;

using log4net.Core;

using System.Diagnostics;

namespace Log4NetTest
{
  class LogicalOperationStackPatternConverter : PatternLayoutConverter
  {
    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      string los = "";

      if (String.IsNullOrWhiteSpace(Option) || String.Compare(Option.Substring(0, 1), "A", true) == 0)
      {
        //Log ALL of stack
        los = Trace.CorrelationManager.LogicalOperationStack.Count > 0 ? 
                string.Join(">>",Trace.CorrelationManager.LogicalOperationStack.ToArray()) :
                "";
      }
      else
      if (String.Compare(Option.Substring(0, 1), "T", true) == 0)
      {
        //Log TOP of stack
        los = Trace.CorrelationManager.LogicalOperationStack.Count > 0 ?
                Trace.CorrelationManager.LogicalOperationStack.Peek().ToString() : "";
      }

      writer.Write(los);
    }
  }
}

The second one allows you to log information stored via CallContext.LogicalSetData. As written, it pulls a value using CallContext.LogicalGetData using a fixed name. It could easily be modified to use the Options property (as demonstrated in the LogicalOperationStack converter) to specify a particular value to pull using CallContext.LogicalGetData.

using log4net;
using log4net.Util;
using log4net.Layout.Pattern;

using log4net.Core;

using System.Runtime.Remoting.Messaging;

namespace Log4NetTest
{
  class LogicalCallContextPatternConverter : PatternLayoutConverter
  {
    protected override void Convert(System.IO.TextWriter writer, LoggingEvent loggingEvent)
    {
      string output = "";
      object value = CallContext.LogicalGetData("MyLogicalData");
      if (value == null)
      {
        output = "";
      }
      else
      {
        output = value.ToString();
      }

      writer.Write(output);
    }
  }
}

Here is how to configure:

  <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d [%t] %logger %-5p [PROP = %property] [LOS.All = %LOS{a}] [LOS.Top = %LOS{t}] [LCC = %LCC] %m%n"/>
    <converter>
      <name value="LOS" />
      <type value="Log4NetTest.LogicalOperationStackPatternConverter" />
    </converter>
    <converter>
      <name value="LCC" />
      <type value="Log4NetTest.LogicalCallContextPatternConverter" />
    </converter>
  </layout>

Here is my test code:

  //Start the threads
  new Thread(TestThis).Start("ThreadA");
  new Thread(TestThis).Start("ThreadB");


  //Execute this code in the threads
private static void TestThis(object name)
{
  var nameStr = (string)name;
  Thread.CurrentThread.Name = nameStr;
  log4net.ThreadContext.Properties["ThreadContext"] = nameStr;
  log4net.LogicalThreadContext.Properties["LogicalThreadContext"] = nameStr;

  CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);

  Trace.CorrelationManager.StartLogicalOperation(nameStr + Thread.CurrentThread.ManagedThreadId);

  logger.Debug("From Thread itself");
  ThreadPool.QueueUserWorkItem(x => 
    {
      logger.Debug("From threadpool Thread_1: " + nameStr);

      Trace.CorrelationManager.StartLogicalOperation(nameStr + Thread.CurrentThread.ManagedThreadId);
      CallContext.LogicalSetData("MyLogicalData", nameStr + Thread.CurrentThread.ManagedThreadId);

      logger.Debug("From threadpool Thread_2: " + nameStr);

      CallContext.FreeNamedDataSlot("MyLogicalData");
      Trace.CorrelationManager.StopLogicalOperation();

      logger.Debug("From threadpool Thread_3: " + nameStr);
    });
}

Here is the output:

Form1: 2011-01-14 09:18:53,145 [ThreadA] Form1 DEBUG [PROP = {LogicalThreadContext=ThreadA, log4net:HostName=WILLIE620, ThreadContext=ThreadA}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ThreadA10] From Thread itself
Form1: 2011-01-14 09:18:53,160 [ThreadB] Form1 DEBUG [PROP = {LogicalThreadContext=ThreadB, log4net:HostName=WILLIE620, ThreadContext=ThreadB}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ThreadB11] From Thread itself
Form1: 2011-01-14 09:18:53,192 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ThreadB11] From threadpool Thread_1: ThreadB
Form1: 2011-01-14 09:18:53,207 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB12>>ThreadB11] [LOS.Top = ThreadB12] [LCC = ThreadB12] From threadpool Thread_2: ThreadB
Form1: 2011-01-14 09:18:53,207 [12] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadB11] [LOS.Top = ThreadB11] [LCC = ] From threadpool Thread_3: ThreadB
Form1: 2011-01-14 09:18:53,207 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ThreadA10] From threadpool Thread_1: ThreadA
Form1: 2011-01-14 09:18:53,223 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA13>>ThreadA10] [LOS.Top = ThreadA13] [LCC = ThreadA13] From threadpool Thread_2: ThreadA
Form1: 2011-01-14 09:18:53,223 [13] Form1 DEBUG [PROP = {log4net:HostName=WILLIE620}] [LOS.All = ThreadA10] [LOS.Top = ThreadA10] [LCC = ] From threadpool Thread_3: ThreadA

When I did this test (and some other testing I have been working on), I created my own "context" stack object (similar to log4net's "stack" implementation) by storing my Stack via CallContext.LogicalSetData rather than via CallContext.SetData (which is how log4net stores it). I found that my stack got jumbled up when I had several ThreadPool threads. Maybe it was from merging the data back to the parent context when the child context exited. I would not have thought that would be the case as in my test I explicitly pushed the new value on entry to the ThreadPool thread and popped it on exit. A similar test with a Trace.CorrelationManager.LogicalOperationStack-based implementation (I wrote an abstraction over it) seemed to behave correctly. I guess that maybe the automatic flowing (down AND back) logic is accounting for CorrelationManager since it is a "known" object in the system???

Some things to note in the output:

1. Trace.CorrelationManager inforamation is stored via CallContext.LogicalSetData so it is "flowed" to child threads. TestThis uses Trace.CorrelationManager.StartLogicalOperation to "push" a logical operation (named for the passed in name) onto the LogicalOperationStack. The first logger.Debug statement in the ThreadPool thread shows that the ThreadPool thread has inherited the same LogicalOperationStack as the parent thread. Inside of the ThreadPool thread, I start a new logical operation which is stacked onto the inherited LogicalOperationStack. You can see the result of that in the second logger.Debug output. Finally, before leaving, I stop the logical operation. The third logger.Debug output shows that.

2. As you can see from the output, CallContext.LogicalSetData is also "flowed" to child threads. In my test code I chose to set a new value into LogicalSetData inside the ThreadPool thread and then clean it up before leaving (FreeNamedDataSlot).

Feel free to try these pattern layout converters and see if you can achieve the results that you are looking for. As I have demonstrated, you should at least be able to reflect in your logging output which ThreadPool threads were started/used by which other (parent?) threads.

Note there are some issues even with CallContext.LogicalSetData in certain environments:

"Child" logical data is merged back into "Parent" logical data: EndInvoke changes current CallContext - why?

Nested multithread operations tracing

(Not an issue, but a good post about Trace.CorrelationManager.ActivityId and Task Parallel Library):

How do Tasks in the Task Parallel Library affect ActivityID?

An oft-linked blog posting about problems with various "context" storage mechanisms in the context of ASP.Net

http://piers7.blogspot.com/2005/11/threadstatic-callcontext-and_02.html

[EDIT]

I have found that maintaining the correct context while heavily (or maybe even not so heavily - my test executes DoLongRunningWork using various Thread/Task/Parallel techniques) using threads can throw some data set with CallContext.LogicalSetData out of whack.

See this question about using Trace.CorrelationManager.ActivityId here on StackOverflow. I posted an answer about using Trace.CorrelationManager.LogicalOperationStack and some of my observations.

Later I used my answer to that question as the basis for my own question about using Trace.CorrelationManager.LogicalOperationStack in the context of Threads/Tasks/Parallel.

I also posted a very similar question on Microsoft's Parallel Extensions forum.

You can read those posts see my observations. To summarize briefly:

With a code pattern like this:

DoLongRunningWork //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
  StartLogicalOperation
  Sleep(3000) //Or do actual work
  StopLogicalOperation

The contents of the LogicalOperationStack remain consistent whether DoLongRunningWork is kicked off by explicit Thread/ThreadPool threads/Tasks/Parallel(.For or .Invoke).

With a code pattern like this:

StartLogicalOperation //In Main thread (or parent thread)
  DoLongRunningWork   //Kicked off as a Thread/Task/Parallel(.For or .Invoke)
    StartLogicalOperation
    Sleep(3000) //Or do actual work
    StopLogicalOperation
StopLogicalOperation

The contents of the LogicalOperationStack remain consistent EXCEPT when DoLongRunningWork is kicked off by Parallel.For or Parallel.Invoke. The reason seems to be related to the fact that Parallel.For and Parallel.Invoke use the main thread as one of the threads to execute the parallel operations.

That means that if you want to enclose the entire parallelized (or threaded) operation as a single logical operation and each iteration (i.e. each invocation of the delegate) as a logical operation nested within the outer operation, most techiques that I tested (Thread/ThreadPool/Task) work correctly. At each iteration, the LogicalOperationStack reflects that there is an outer task (for the main thread) and an inner task (the delegate).

If you use Parallel.For or Parallel.Invoke, the LogicalOperationStack does not work correctly. In the sample code in the posts that linked above, the LogicalOperationStack should never have more than 2 entries. One for the main thread and one for the delegate. When using Parallel.For or Parallel.Invoke the LogicalOperationStack will eventually get many more than 2 entries.

Using CallContext.LogicalSetData fares even worse (at least if trying to emulate LogicalOperationStack by storing a Stack with LogicalSetData). With a similar call pattern as above (the one with the enclosing logical operation as well as the delegate logical operation), a Stack stored with LogicalSetData and maintained identically (as far as I can tell) will get corrupted in almost all cases.

CallContext.LogicalSetData might work better for simpler types or for types that are not modified within the "logical thread". If I were to store a dictionary of values with LogicalSetData (similar to log4net.LogicalThreadContext.Properties), it would probably be inherited successfully by child threads/Tasks/etc.

I don't have any great explanations for exactly why this is happening or the best way to work around it. It might be that the way I was testing "context" went a little overboard, or it might not.

If you do look into this some more, you might try out the test programs that I posted in the links above. The test programs only test the LogicalOperationStack. I have performed similar tests with more complicated code by making a context abstraction that supports an interface like IContextStack. One implementation uses a Stack stored via CallContext.LogicalSetData (similar to how log4net's LogicalThreadContext.Stacks is stored, except that I used LogicalSetData rather than SetData). The other implementation implements that interface over Trace.CorrelationManager.LogicalOperationStack. That makes it easy for me to run the same tests with different context implementations.

Here is my IContextStack interface:

  public interface IContextStack
  {
    IDisposable Push(object item);
    object Pop();
    object Peek();
    void Clear();
    int Count { get; }
    IEnumerable<object> Items { get; }
  }

Here is the LogicalOperationStack-based implementaiton:

  class CorrelationManagerStack : IContextStack, IEnumerable<object>
  {
    #region IContextStack Members

    public IDisposable Push(object item)
    {
      Trace.CorrelationManager.StartLogicalOperation(item);

      return new StackPopper(Count - 1, this);
    }

    public object Pop()
    {
      object operation = null;

      if (Count > 0)
      {
        operation = Peek();
        Trace.CorrelationManager.StopLogicalOperation();
      }

      return operation;
    }

    public object Peek()
    {
      object operation = null;

      if (Count > 0)
      {
        operation = Trace.CorrelationManager.LogicalOperationStack.Peek();
      }

      return operation;
    }

    public void Clear()
    {
      Trace.CorrelationManager.LogicalOperationStack.Clear();
    }

    public int Count
    {
      get { return Trace.CorrelationManager.LogicalOperationStack.Count; }
    }

    public IEnumerable<object> Items
    {
      get { return Trace.CorrelationManager.LogicalOperationStack.ToArray(); }
    }

    #endregion

    #region IEnumerable<object> Members

    public IEnumerator<object> GetEnumerator()
    {
      return (IEnumerator<object>)(Trace.CorrelationManager.LogicalOperationStack.ToArray().GetEnumerator());
    }

    #endregion

    #region IEnumerable Members

    System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator()
    {
      return Trace.CorrelationManager.LogicalOperationStack.ToArray().GetEnumerator();
    }

    #endregion

  }

Here is the CallContext.LogicalSetData-based implementation:

  class ThreadStack : IContextStack, IEnumerable<object>
  {
    const string slot = "EGFContext.ThreadContextStack";

    private static Stack<object> GetThreadStack
    {
      get
      {
        Stack<object> stack = CallContext.LogicalGetData(slot) as Stack<object>;
        if (stack == null)
        {
          stack = new Stack<object>();
          CallContext.LogicalSetData(slot, stack);
        }
        return stack;
      }
    }

    #region IContextStack Members

    public IDisposable Push(object item)
    {
      Stack<object> s = GetThreadStack;
      int prevCount = s.Count;
      GetThreadStack.Push(item);

      return new StackPopper(prevCount, this);
    }

    public object Pop()
    {
      object top = GetThreadStack.Pop();

      if (GetThreadStack.Count == 0)
      {
        CallContext.FreeNamedDataSlot(slot);
      }

      return top;
    }

    public object Peek()
    {
      return Count > 0 ? GetThreadStack.Peek() : null;
    }

    public void Clear()
    {
      GetThreadStack.Clear();

      CallContext.FreeNamedDataSlot(slot);
    }

    public int Count { get { return GetThreadStack.Count; } }

    public IEnumerable<object> Items 
    { 
      get
      {
        return GetThreadStack;
      }
    }

    #endregion

    #region IEnumerable<object> Members

    public IEnumerator<object> GetEnumerator()
    {
      return GetThreadStack.GetEnumerator();
    }

    #endregion

    #region IEnumerable Members

    System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator()
    {
      return GetThreadStack.GetEnumerator();
    }

    #endregion
  }

Here is the StackPopper used by both:

  internal class StackPopper : IDisposable
  {
    int pc;
    IContextStack st;

    public StackPopper(int prevCount, IContextStack stack)
    {
      pc = prevCount;
      st = stack;
    }

    #region IDisposable Members

    public void Dispose()
    {
      while (st.Count > pc)
      {
        st.Pop();
      }
    }

    #endregion
  }

It's a lot to digest, but maybe you will find some of this useful!

Answer 2

The context information in log4net is per thread, so every time you start a new thread you have to add your context information to it. You can use properties, or you can use the NDC. The NDC is per thread too, so you would still have to add it to each thread's context at some point, which might or might not be what you're looking for. It would save you from adding it to the message itself though. In your example it would be something like this:

ThreadPool.QueueUserWorkItem(x => NDC.Push("nameStr")); log.Debug("From threadpool Thread: " + nameStr));

Here's a link to the documentation for NDC.

All in all the effect is similar to using properties, just like what you have in your example. The only difference is that the NDC can be stacked so that every time that you push a value on the stack it will get concatenated to the message. It also supports the using statement, which makes for cleaner code.