title: log4net LogicalThreadContext not working
body: <p>I have what is either a bug in log4net, or a misunderstanding on my part.</p>
  
  <p>I'm trying to use <code>LogicalThreadContext</code> 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 <code>LogicalThreadContext</code> over <code>ThreadContext</code>.</p>
  
  <p>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:</p>
  
  <pre><code>[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");
      }
  }
  </code></pre>
  
  <p>My log4net configuration looks like this:</p>
  
  <pre><code>&lt;?xml version="1.0" encoding="utf-8" ?&gt;
  
  &lt;configuration&gt;
      &lt;configSections&gt;
          &lt;section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" /&gt;
      &lt;/configSections&gt;
  
      &lt;log4net&gt;
          &lt;appender name="FileAppender" type="log4net.Appender.FileAppender"&gt;
              &lt;file value="log.txt" /&gt;
              &lt;appendToFile value="true" /&gt;
              &lt;layout type="log4net.Layout.PatternLayout"&gt;
                  &lt;conversionPattern value="[%thread]|[%property{foo}]|%message%newline"/&gt;
              &lt;/layout&gt;
          &lt;/appender&gt;
  
          &lt;root&gt;
              &lt;level value="DEBUG" /&gt;
              &lt;appender-ref ref="FileAppender" /&gt;
          &lt;/root&gt;
      &lt;/log4net&gt;
  &lt;/configuration&gt;
  </code></pre>
  
  <p>And my output looks like this:</p>
  
  <pre><code>[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
  </code></pre>
  
  <p>As you can see, the data I push onto the LTC stack is only present in the logging statements made <em>on the same thread</em>. The log statement made by the background thread is lacking the contextual data. Debugging through the test I could see that, indeed, that <code>LogicalThreadContext.Stacks.Count</code> is zero on the background thread.</p>
  
  <p>Digging into the log4net source, I found it utilizing the <a href="http://msdn.microsoft.com/en-us/library/system.runtime.remoting.messaging.callcontext.aspx" rel="noreferrer"><code>CallContext</code></a> 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.</p>
  
  <p><code>CallContext</code> has two sets of methods with which context information can be stored and retrieved: <code>GetData</code>/<code>SetData</code> and <code>LogicalGetData</code>/<code>LogicalSetData</code>. The documentation is very light on details regarding the difference between these two sets of methods, but the examples use <code>GetData</code>/<code>SetData</code>. And so does log4net's <code>LogicalThreadContext</code>.</p>
  
  <p>A quick test showed that <code>GetData</code>/<code>SetData</code> exhibits the same problem - data does not propagate across threads. I thought I'd give <code>LogicalGetData</code>/<code>LogicalSetData</code> a go instead:</p>
  
  <pre><code>[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 &lt; 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();
      }
  }
  </code></pre>
  
  <p>This test passes - contextual information is successfully propagated across threads when using <code>LogicalGetData</code>/<code>LogicalSetData</code>.</p>
  
  <p>So my question is this: <strong>has log4net gotten this wrong? Or is there something I'm missing?</strong></p>
  
  <p><strong>UPDATE:</strong> I also tried doing a custom build of log4net with its <code>LogicalThreadContextProperties</code> 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.</p>