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

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

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

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

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

这是NDC文档的链接。

总而言之，效果类似于使用属性，就像您在示例中所拥有的那样。 唯一的区别是NDC可以堆叠，这样每次在堆栈上推送一个值时，它都会连接到消息。 它还支持using语句，这使代码更清晰。

更新：12/11/2014 – 请在此处查看我的post的第一部分：

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

最近的更新。 Log4Net的LogicalThreadContext最近有所更新（最近几年），现在它可以正常工作。 链接post中的更新提供了一些细节。

结束更新。

这是一个可能对您有所帮助的想法。 部分问题是log4net上下文对象（ThreadContext和LogicalThreadContext）不会将其属性“流”到“子”线程。 LogicalThreadContext给出了错误的印象，但它没有。 在内部，它使用CallContext.SetData来存储其属性。 通过SetData的数据集附加到THREAD，但它不是由子线程“inheritance”的。 所以，如果你通过这样设置一个属性： 

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

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

如果您可以通过CallContext.LogicalSetData保存属性（请参阅上面的链接），那么属性将“流”到任何子线程（或由其inheritance）。 所以，如果你能做到这样的事情： 

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

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

有关使用CallContext.LogicalSetData的更多信息，请参阅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); } } }

以下是配置方法：

这是我的测试代码： 

  //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.SetData存储我的堆栈，创建了我自己的“上下文”堆栈对象（类似于log4net的“堆栈”实现）。这是log4net存储它的方式）。 我发现当我有几个ThreadPool线程时，我的堆栈混乱了。 也许是在子环境退出时将数据合并回父上下文。 我不会想到会出现这种情况，因为在我的测试中我明确地将新值输入到ThreadPool线程并在退出时弹出它。 使用基于Trace.CorrelationManager.LogicalOperationStack的实现（我在其上写了一个抽象）的类似测试似乎行为正确。 我想也许自动流动（向下和向后）逻辑考虑了CorrelationManager，因为它是系统中的“已知”对象???

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

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

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

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

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

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

嵌套multithreading操作跟踪

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

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

一个经常链接的博客文章，讲述ASP.Net上下文中各种“上下文”存储机制的问题

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

[编辑]

我发现使用线程大量（或者甚至可能不那么重 – 我的测试使用各种线程/任务/并行技术执行DoLongRunningWork）维​​护正确的上下文可以使用CallContext.LogicalSetData抛出一些数据集。

请参阅有关在StackOverflow上使用Trace.CorrelationManager.ActivityId的此问题 。 我发布了一个关于使用Trace.CorrelationManager.LogicalOperationStack和我的一些观察的答案。

后来我用我对这个问题的回答作为我自己关于在Threads / Tasks / Parallel上下文中使用Trace.CorrelationManager.LogicalOperationStack的问题的基础。

我还在微软的Parallel Extensions论坛上发布了一个非常类似的问题 。

您可以阅读这些post，看看我的观察。 简要总结一下：

使用这样的代码模式： 

 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

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

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

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

使用CallContext.LogicalSetData的情况更糟（至少如果试图通过使用LogicalSetData存储堆栈来模拟LogicalOperationStack）。 使用与上面类似的调用模式（具有封闭逻辑操作以及委托逻辑操作的调用模式），与LogicalSetData一起存储并且相同维护的堆栈（据我所知）将在几乎所有情况下都被破坏。

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

对于为什么会发生这种情况或解决问题的最佳方法，我没有任何重要的解释。 可能是我测试“上下文”的方式有点过分，或者可能没有。

如果您对此进行了更多研究，可以尝试我在上面的链接中发布的测试程序。 测试程序仅测试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 Items { get; } }

这是基于LogicalOperationStack的实现： 

  class CorrelationManagerStack : IContextStack, IEnumerable { #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 Items { get { return Trace.CorrelationManager.LogicalOperationStack.ToArray(); } } #endregion #region IEnumerable Members public IEnumerator GetEnumerator() { return (IEnumerator)(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 { const string slot = "EGFContext.ThreadContextStack"; private static Stack GetThreadStack { get { Stack stack = CallContext.LogicalGetData(slot) as Stack; if (stack == null) { stack = new Stack(); CallContext.LogicalSetData(slot, stack); } return stack; } } #region IContextStack Members public IDisposable Push(object item) { Stack 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 Items { get { return GetThreadStack; } } #endregion #region IEnumerable Members public IEnumerator 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 }

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

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

一个选项是代替单个静态记录器实例，您可以通过使用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）从外部注入所需的日志记录行为。

Interesting Posts

创建动态变量名称

解析字符串以浮点数C＃

在wpf中禁止/阻止选择禁用的combobox项目

每当更新数据库时更新C＃客户端

实体或复杂类型…不能在LINQ to Entities查询中构造

InternalEquals的实现在哪里（object objA，object objB）

详细了解.NET的工作原理

entity framework：如何表达包含的LIKE语句

从T4模板调用同一项目中的类

使用FTP和C＃下载所有文件