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

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.

Answer 2

From my pov the only possibility would be to change the thread creation inside the modules as otherwise you can not add any relevant context.
If you can change the code, then you would create a class which would inherit from the used System.Threading class (e.g. Thread in your example) and would call the super class and add the relevant logging context.
There are some other tricks possible, but this would be a clean approach without any dirty tricks.

Answer 3

One option is instead of a single static logger instance, you could create one for each thread by marking it with the ThreadStatic attribute. Then you can add your context to the logger and it will be applied to each log entry once the context is set.

[ThreadStatic]
static readonly log4net.ILog log = log4net.LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);

However, you'd still have the issue of getting the context set within each thread. For that, I recommend abstracting the creation of your loggers. Use a factory method and require a call to CreateLogger() to retrieve an instance of the logger. Within the factory, use ThreadStatic and set the ThreadContext property when a logger is initialized.

It does require a little code modification, but not a ton.

Finally, a more elaborate option is to use an AOP (Aspect Oriented Programming) framework such as LinFu to inject your desired logging behavior externally.