Log4net LogicalThreadContext not working

Question

I have either an error in log4net, or a misunderstanding on my part.

I am trying to use a LogicalThreadContext to associate some data with a call context and propagate it to any log entries created by any thread in this context. This is an implied advantage of LogicalThreadContext over ThreadContext .

I was not able to get the distribution to work, so I put together a simple unit test to see if it would work, but it’s not. Here he 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 conclusion is as follows:

 [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 that I click on the LTC stack is only present in the logging statements executed on the same thread. The journal statement made by the background thread is missing context data. Debugging through the test, I could see that, indeed, LogicalThreadContext.Stacks.Count is zero in the background thread.

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

CallContext has two sets of methods with which you can save and retrieve contextual information: GetData / SetData and LogicalGetData / LogicalSetData . The documentation is very easy in detail regarding the difference between the two sets of methods, but the examples use GetData / SetData . And log4net LogicalThreadContext .

A quick test showed that GetData / SetData exhibits the same problem - data is not propagated through streams. I thought I would 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 distributed across streams when using LogicalGetData / LogicalSetData .

So my question is this: does log4net have this wrong? Or am I missing something?

UPDATE: I also tried to do a custom build of log4net with my LogicalThreadContextProperties , modified according to my findings above. I restarted my initial test and it worked. It just amazes me as too obvious a problem for a product used by so many people, so I have to assume that I missed something.

Answer 1

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

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

There is a link to a publication by Nicko Cadell, one of the authors of log4net, about how LogicalThreadContext works. It talks about elements stored in CallContext that support ILogicalThreadAffinative, automatically propagate to child threads, but log4net does not use ILogicalThreadAffinative. It does not mention anything about using CallContext.LogicalSetData, which, as you found, causes CallContext data to automatically propagate to child threads without having to execute ILogicalThreadAffinative.

In conclusion, I do not think you are missing something. I really think log4net got this wrong.

I understand that you did not request any code, but here are some of the work that I did a few months ago when I looked in log4net, CallContext, PatternLayoutConverter, etc.

Firstly, the logical flow object that I collected several months ago. I wrote it to mimic the magazine context abbreviations provided by the Castle logging tool.

  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 the log4net PatternLayoutConverter template (which was written at a different time, primarily as an experiment, to learn about log4net and CallContext). He expects the Option property to specify a specific named value from the context of the boolean call. It would not be easy to write a similar PatternLayoutConverter, which retrieves the dictionary from the logical context based on the above name, and then uses the Option parameter to index 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 a dictionary schema, as in the first code example, PatternLayoutConverter can look something like this (without glitches and unverified):

  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