如何使用 log4net 记录 Threadpool 线程的正确上下文？

Question

我正在尝试找到一种方法来从一堆线程中记录有用的上下文。问题是，许多代码是在通过线程池线程到达的事件上处理的（据我所知），因此它们的名称与任何上下文都没有关系。这个问题可以用下面的代码来演示：

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

转换模式是：

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

输出如下：

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

正如您所看到的，最后两行没有有用信息的名称来区分 2 个线程，除了手动将名称添加到消息中（我想避免）。如何将名称/上下文获取到线程池线程的日志中，而无需在每次调用时将其添加到消息中或需要在每次回调中再次设置属性。

Answer 1

更新：
2014 年 12 月 11 日 - 请参阅我的帖子的第一部分：

log4net.ThreadContext 和 log4net.LogicalThreadContext 有什么区别？

最近的更新。 Log4Net 的 LogicalThreadContext 最近（在过去几年中）进行了一些更新，因此现在可以正常工作。链接帖子中的更新提供了一些详细信息。

结束更新。

这是一个可能对您有帮助的想法。部分问题在于 log4net 上下文对象（ThreadContext 和 LogicalThreadContext）不会将其属性“流”到“子”线程。 LogicalThreadContext 给人一种错误的印象，它确实如此，但事实并非如此。在内部它使用 CallContext.SetData 来存储其属性。通过 SetData 设置的数据附加到线程，但它不会被子线程“继承”。因此，如果您通过如下方式设置属性：

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

该属性将可通过 %property 模式转换器进行记录，并且在从您首先设置属性的同一线程记录时将包含一个值，但它不会包含值在从该线程生成的任何子线程中。

如果您可以通过 CallContext.LogicalSetData（请参阅上面的链接）保存属性，则属性将“流向”（或由）任何子线程继承。因此，如果您可以执行以下操作：

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

那么“MyLogicalData”将在您设置它的线程以及任何子线程中可用。

请参阅Jeffrey Richter 的这篇博客文章 了解有关使用 CallContext.LogicalSetData 的更多信息。

您可以通过 CallContext.LogicalSetData 轻松存储您自己的信息，并通过编写您自己的 PatternLayoutConverter.我附上了两个新的 PatternLayoutConverters 的一些示例代码。

第一个允许您记录存储在 Trace.CorrelationManager 中的信息 的LogicalOperationStack。布局转换器允许您记录 LogicalOperationStack 的顶部或整个 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);
    }
  }
}

第二个允许您记录通过 CallContext.LogicalSetData 存储的信息。正如所写，它使用 CallContext.LogicalGetData 使用固定名称提取值。可以轻松修改它以使用 Options 属性（如 LogicalOperationStack 转换器中所示）来指定要使用 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);
    }
  }
}

以下是如何配置：

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

这是我的测试代码：

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

这是输出：

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

当我进行此测试（以及我一直在进行的其他一些测试）时，我创建了自己的“上下文”堆栈对象（类似于 log4net 的“堆栈”）通过 CallContext.LogicalSetData 而不是通过 CallContext.SetData （这就是 log4net 存储它的方式）来存储我的堆栈。我发现当我有多个 ThreadPool 线程时，我的堆栈变得混乱。也许是因为当子上下文退出时将数据合并回父上下文。我没想到会出现这种情况，因为在我的测试中，我在进入 ThreadPool 线程时显式地将新值推送到线程池线程，并在退出时将其弹出。使用基于 Trace.CorrelationManager.LogicalOperationStack 的实现（我在其上编写了一个抽象）进行的类似测试似乎表现正确。我想也许自动流动（向下和向后）逻辑正在考虑 CorrelationManager，因为它是系统中的“已知”对象？？？

输出中需要注意的一些事项：

1. Trace.CorrelationManager 信息通过 CallContext.LogicalSetData 存储，因此它“流”到子线程。 TestThis 使用 Trace.CorrelationManager.StartLogicalOperation 将逻辑操作（根据传入的名称命名）“推送”到 LogicalOperationStack 上。 ThreadPool线程中的第一个logger.Debug语句显示ThreadPool线程继承了与父线程相同的LogicalOperationStack。在 ThreadPool 线程内部，我启动一个新的逻辑操作，该操作堆叠到继承的 LogicalOperationStack 上。您可以在第二个 logger.Debug 输出中看到结果。最后，在离开之前，我停止了逻辑运算。第三个 logger.Debug 输出显示。

2. 从输出中可以看到，CallContext.LogicalSetData 也“流”到了子线程。在我的测试代码中，我选择在 ThreadPool 线程内的 LogicalSetData 中设置一个新值，然后在离开之前清理它 (FreeNamedDataSlot)。

请随意尝试这些图案布局转换器，看看是否可以获得您正在寻找的结果。正如我所演示的，您至少应该能够在日志输出中反映哪些 ThreadPool 线程是由哪些其他（父？）线程启动/使用的。

请注意，即使在某些环境中使用 CallContext.LogicalSetData 也存在一些问题：

“子”逻辑数据被合并回“父”逻辑数据：
EndInvoke 更改当前 CallContext - 为什么？

嵌套多线程操作跟踪

（不是问题，但关于 Trace.CorrelationManager.ActivityId 和任务并行库的好文章）：

任务并行库中的任务如何影响 ActivityID？

有关 ASP.Net 上下文中各种“上下文”存储机制问题的链接博客文章

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

[编辑]

我发现在大量（或者甚至可能不那么严重 - 我的测试使用各种线程/任务/并行技术执行 DoLongRunningWork），使用线程可能会导致 CallContext.LogicalSetData 的某些数据集不正常。

请参阅有关使用 Trace.CorrelationManager.ActivityId 的问题 在 StackOverflow 上。我发布了有关使用 Trace.CorrelationManager.LogicalOperationStack 的答案以及我的一些观察结果。

后来我用我对这个问题的回答作为我自己的问题的基础在线程/任务/并行上下文中使用 Trace.CorrelationManager.LogicalOperationStack。

我还发布了非常相似Microsoft 并行扩展论坛上的问题。

你可以阅读这些帖子看看我的观察。简单总结一下：

使用这样的代码模式：

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

无论 DoLongRunningWork 是由显式 Thread/ThreadPool 线程/Tasks/Parallel(.For 或 .Invoke) 启动，LogicalOperationStack 的内容都保持一致。

使用如下代码模式：

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

LogicalOperationStack 的内容保持一致，除非 DoLongRunningWork 由 Parallel.For 或 Parallel.Invoke 启动。原因似乎与 Parallel.For 和 Parallel.Invoke 使用主线程作为执行并行操作的线程之一有关。

这意味着，如果您想将整个并行（或线程）操作作为单个逻辑操作，并将每次迭代（即委托的每次调用）作为嵌​​套在外部操作中的逻辑操作，我测试的大多数技术（线程/线程池/任务）正常工作。在每次迭代时，LogicalOperationStack 都会反映出存在一个外部任务（用于主线程）和一个内部任务（委托）。

如果您使用 Parallel.For 或 Parallel.Invoke，LogicalOperationStack 将无法正常工作。在上面链接的帖子的示例代码中，LogicalOperationStack 不应有超过 2 个条目。一个用于主线程，一个用于委托。当使用 Parallel.For 或 Parallel.Invoke 时，LogicalOperationStack 最终将获得超过 2 个条目。

使用 CallContext.LogicalSetData 的效果甚至更糟（至少如果尝试通过使用 LogicalSetData 存储 Stack 来模拟 LogicalOperationStack 的话）。使用与上面类似的调用模式（具有封闭逻辑操作和委托逻辑操作的调用模式），用 LogicalSetData 存储并以相同方式维护的堆栈（据我所知）几乎在所有情况下都会被损坏。

CallContext.LogicalSetData 对于更简单的类型或未在“逻辑线程”内修改的类型可能效果更好。如果我用 LogicalSetData 存储值字典（类似于 log4net.LogicalThreadContext.Properties），它可能会被子线程/任务/等成功继承。

我没有任何很好的解释来解释为什么会发生这种情况，也没有最好的解决方法。我测试“上下文”的方式可能有点过分，也可能没有。

如果您确实对此进行了更多研究，您可以尝试我在上面的链接中发布的测试程序。测试程序仅测试LogicalOperationStack。我通过创建支持 IContextStack 等接口的上下文抽象，使用更复杂的代码执行了类似的测试。一种实现使用通过 CallContext.LogicalSetData 存储的 Stack（类似于 log4net 的 LogicalThreadContext.Stacks 的存储方式，除了我使用 LogicalSetData 而不是 SetData）。另一个实现通过 Trace.CorrelationManager.LogicalOperationStack 实现该接口。这使我可以轻松地使用不同的上下文实现运行相同的测试。

这是我的 IContextStack 接口：

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

这是基于 LogicalOperationStack 的实现：

  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

  }

这是基于 CallContext.LogicalSetData 的实现：

  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
  }

这是两者使用的 StackPopper：

  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
  }

需要消化的内容很多，但也许您会发现其中一些有用！

Answer 2

log4net 中的上下文信息是针对每个线程的，因此每次启动新线程时，都必须向其中添加上下文信息。您可以使用属性，也可以使用 NDC。 NDC 也是针对每个线程的，因此您仍然需要在某个时刻将其添加到每个线程的上下文中，这可能是也可能不是您正在寻找的内容。不过，它可以让您免于将其添加到消息本身中。在您的示例中，它会是这样的：

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

这是 文档的链接对于 NDC。

总而言之，效果与使用属性类似，就像示例中的效果一样。唯一的区别是 NDC 可以堆叠，以便每次将值压入堆栈时，它都会连接到消息。它还支持 using 语句，这使得代码更清晰。

Answer 3

从我的角度来看，唯一的可能性是更改模块内的线程创建，否则您无法添加任何相关上下文。
如果您可以更改代码，那么您将创建一个从所使用的 System.Threading 类（例如示例中的 Thread）继承的类，并调用超类并添加相关的日志记录上下文。
还有一些其他可能的技巧，但这将是一个干净的方法，没有任何肮脏的技巧。

Answer 4

一种选择是代替单个静态记录器实例，您可以通过使用 ThreadStatic 属性并在属性 getter 中初始化。然后，您可以将上下文添加到记录器，一旦设置了上下文，它将应用于每个日志条目。

[ThreadStatic]
static readonly log4net.ILog _log;

static string log {
   get {
     if (null == _log) {
         _log = log4net.LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
     }
     return _log;
   }
}

但是，您仍然会遇到在每个线程中设置上下文的问题。为此，我建议抽象记录器的创建。使用工厂方法并需要调用 CreateLogger() 来检索记录器的实例。在工厂内，使用 ThreadStatic 并在初始化记录器时设置 ThreadContext 属性。

它确实需要一些代码修改，但不需要太多。

更精细的选择是使用 AOP（面向方面​​编程）框架，例如 LinFu 从外部注入您想要的日志记录行为。