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

【问题标题】：How to log correct context with Threadpool threads using log4net?如何使用 log4net 使用 Threadpool 线程记录正确的上下文？
【发布时间】：2011-02-22 08:42:48
【问题描述】：

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

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 个线程，除了手动将名称添加到消息中（我想避免）。如何将名称/上下文获取到线程池线程的日志中，而无需在每次调用时将其添加到消息中，也无需在每次回调中再次设置属性。

【问题讨论】：

@My Other Me -（添加此评论希望您能在下面我较长的评论中收到她的通知）请参阅我的评论/问题，以回应您在 2010 年 11 月 4 日对@TskTsk 的回答的评论

标签： c# multithreading log4net threadpool

【解决方案1】：

更新： 2014 年 12 月 11 日 - 在此处查看我帖子的第一部分：

What is the difference between log4net.ThreadContext and 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”将在您设置它的线程以及任何子线程中可用。

有关使用 CallContext.LogicalSetData 的更多信息，请参阅 this blog posting by Jeffrey Richter。

您可以通过 CallContext.LogicalSetData 轻松存储您自己的信息，并通过编写您自己的PatternLayoutConverter 将其用于 log4net 的日志记录。我为两个新的 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

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

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

Trace.CorrelationManager 信息通过 CallContext.LogicalSetData 存储，因此它“流向”子线程。 TestThis 使用 Trace.CorrelationManager.StartLogicalOperation 将逻辑操作（以传入的名称命名）“推送”到 LogicalOperationStack。 ThreadPool 线程中的第一个 logger.Debug 语句表明 ThreadPool 线程继承了与父线程相同的 LogicalOperationStack。在 ThreadPool 线程内部，我启动了一个新的逻辑操作，该操作堆叠到继承的 LogicalOperationStack 上。您可以在第二个 logger.Debug 输出中看到结果。最后，在离开之前，我停止了逻辑运算。第三个 logger.Debug 输出显示。
从输出中可以看出，CallContext.LogicalSetData 也“流向”子线程。在我的测试代码中，我选择在 ThreadPool 线程内为 LogicalSetData 设置一个新值，然后在离开之前将其清理 (FreeNamedDataSlot)。

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

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

“子”逻辑数据合并回“父”逻辑数据： EndInvoke changes current CallContext - why?

Nested multithread operations tracing

（不是问题，而是关于 Trace.CorrelationManager.ActivityId 和任务并行库的好帖子）：

How do Tasks in the Task Parallel Library affect ActivityID?

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

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

[编辑]

我发现，在使用线程大量（或者甚至可能不那么严重——我的测试使用各种线程/任务/并行技术执行 DoLongRunningWork）维护正确的上下文时，可能会使带有 CallContext.LogicalSetData 的一些数据集失控。

在 StackOverflow 上查看 this question about using Trace.CorrelationManager.ActivityId。我发布了关于使用 Trace.CorrelationManager.LogicalOperationStack 的答案以及我的一些观察结果。

后来我以我对该问题的回答为基础for my own question about using Trace.CorrelationManager.LogicalOperationStack in the context of Threads/Tasks/Parallel。

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

使用这样的代码模式：

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 存储堆栈来模拟 LogicalOperationStack 时）。使用与上述类似的调用模式（具有封闭逻辑操作和委托逻辑操作的调用模式），使用 LogicalSetData 存储并保持相同（据我所知）的堆栈几乎在所有情况下都会损坏。

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

对于发生这种情况的确切原因或解决它的最佳方法，我没有任何很好的解释。可能是我测试“上下文”的方式有点过火了，也可能不是。

如果您确实对此进行了更多研究，则可以尝试我在上面链接中发布的测试程序。测试程序只测试LogicalOperationStack。通过创建支持 IContextStack 之类的接口的上下文抽象，我使用更复杂的代码执行了类似的测试。一种实现使用通过 CallContext.LogicalSetData 存储的堆栈（类似于 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
  }

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

【讨论】：

很棒的细节。下次我需要做这样的事情时，我需要回顾一下这个答案。
@My Other Me - 我添加了一些关于自首次发布此答案以来所学知识的更多细节。它可能对您有用，也可能没有。

【解决方案2】：

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

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

这是documentation for NDC的链接。

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

【讨论】：

谢谢，但我要避免的是在每个绑定事件开始时都需要做一些事情。我希望有一种方法可以在创建线程时只设置一次线程名称或上下文，然后就不必再担心了。
NDC 根据 logging.apache.org/log4net/release/sdk/log4net.NDC.html 已弃用
不是我问题的最终解决方案，但它让我走上了可行的道路。
@My Other Me - 从你最近的评论中我可以看出你想出了一些可行的方法。我很好奇你最终做了什么来解决这个问题。如果您有时间，可以添加对您所做工作的简要描述，也许还可以添加一个代码示例（也许您是如何调用 log4net 和/或操作 NDC 的？）。谢谢。
@wageoghe：（我希望你能明白）我们想做什么就碰壁了。我们意识到命名工作线程是不好的，因为名称出现在应用程序的其他区域并导致严重混乱。我最终在接收事件的类实例中获得了所需的线程名称，并在事件到达时设置线程名称并在退出时取消设置它。我仍在寻找一个优雅的解决方案。

【解决方案3】：

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

【讨论】：

【解决方案4】：

一个选项不是单个静态记录器实例，您可以通过使用ThreadStatic 属性标记每个线程并在属性获取器中初始化来为每个线程创建一个。然后你可以将你的上下文添加到记录器中，一旦设置了上下文，它将应用于每个日志条目。

[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，在外部注入所需的日志记录行为。

【讨论】：

字段初始化器不会在每个线程上单独调用，不应与ThreadStatic一起使用
很好@Vlad。事实上，MSDN 说“不要为标有 ThreadStaticAttribute 的字段指定初始值，因为这种初始化只发生一次，当类构造函数执行时，因此只影响一个线程。”我已通过添加静态属性 getter 来初始化字段来纠正错误。