log4net 逻辑线程上下文不工作

Question

我的问题是 log4net 中的错误，或者是我的误解。

我正在尝试使用LogicalThreadContext 将一些数据与调用上下文相关联，并将其传播到该上下文中任何线程所做的任何日志语句。这就是LogicalThreadContext 相对于ThreadContext 的据称优势。

我无法让传播工作，所以我整理了一个简单的单元测试来看看它是否会工作，但它不会。这里是：

[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");
    }
}

我的 log4net 配置如下所示：

<?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>

我的输出如下所示：

[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

如您所见，我推送到 LTC 堆栈的数据仅存在于在同一线程上生成的日志记录语句中。后台线程的日志语句缺少上下文数据。通过测试进行调试，我可以看到，LogicalThreadContext.Stacks.Count 在后台线程上确实为零。

深入研究 log4net 源代码，我发现它使用了 CallContext 类。这个类做它在锡上所说的 - 它允许存储和检索当前“调用”的上下文。它是如何在低级别做到这一点的，我不知道。

CallContext 有两组可以存储和检索上下文信息的方法：GetData/SetData 和LogicalGetData/LogicalSetData。该文档对这两组方法之间差异的详细信息非常了解，但示例使用GetData/SetData。 log4net 的LogicalThreadContext 也是如此。

快速测试表明GetData/SetData 表现出同样的问题——数据不会跨线程传播。我想我应该试试LogicalGetData/LogicalSetData：

[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();
    }
}

此测试通过 - 使用 LogicalGetData/LogicalSetData 时，上下文信息成功跨线程传播。

所以我的问题是：log4net 搞错了吗？还是我遗漏了什么？

更新：我还尝试根据我上面的发现对其 LogicalThreadContextProperties 类进行自定义构建 log4net。我重新运行了我的初始测试，它成功了。对于这么多人使用的产品来说，这让我觉得问题太明显了，所以我不得不假设我遗漏了一些东西。

Answer 1

这是我前段时间问过的一个问题，关于 ThreadContext 和 LogicalThreadContext 之间的区别：

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

其中有一个链接，指向 log4net 的作者之一 Nicko Cadell 关于 LogicalThreadContext 如何工作的帖子。他谈到了存储在 CallContext 中的项目，这些项目支持 ILogicalThreadAffinative 被自动传播到子线程，但 log4net 不使用 ILogicalThreadAffinative。他没有提到任何关于使用 CallContext.LogicalSetData 的内容，正如您所发现的，这会导致 CallContext 数据自动传播到子线程，而无需实现 ILogicalThreadAffinative。

总之，我认为您没有遗漏任何东西。我确实认为 log4net 弄错了。

我知道您并没有要求任何代码，但这是我几个月前在研究 log4net、CallContext、PatternLayoutConverter 等时所做的一些工作。

首先，我几个月前拼凑的一个“逻辑线程上下文”对象。我编写它是为了模仿 Castle 日志记录工具提供的日志记录上下文抽象。

  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; }
    }
  }

这是一个 log4net PatternLayoutConverter（它是在不同的时间编写的，主要是作为帮助了解 log4net 和 CallContext 的实验）。它期望 Option 属性从逻辑调用上下文中指定一个特定的命名值。写一个类似的PatternLayoutConverter，根据上面的名字从逻辑上下文中获取字典，然后使用Option参数索引到字典中，应该不会太难。

  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;
      }
    }
  }

要在第一个代码示例中使用字典方案，PatternLayoutConverter 可能看起来像这样（未编译和未经测试）：

  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;
      }
    }
  }

祝你好运！