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

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

log4net中的上下文信息是每个线程，因此每次启动一个新线程时都必须添加上下文信息。您可以使用属性，也可以使用NDC。 NDC也是每个线程，因此您仍然必须将其添加到每个线程的上下文中，这可能是也可能不是您想要的。尽管如此，它可以避免将它添加到消息本身。在您的例子，将是这样的：

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

这里给documentation for NDC的链接。

总而言之，所有这些效果都与使用属性类似，就像您在示例中所使用的一样。唯一的区别是可以堆叠NDC，以便每次在堆栈上推送一个值时，都会将其与消息连接起来。它还支持使用语句，它使代码更简洁。

Answer 2

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

Answer 3

一种选择是使用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）在外部注入所需的日志记录行为。

Answer 4

UPDATE： 2014年12月11日 - 在这里看到我的文章的第一部分：

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

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

END UPDATE。

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

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

该属性将通过百分比特性模式转换为loggable并从那里您设置该属性在首位在同一个线程登录时将包含一个值，但它不会包含从该线程派生的任何子线程中的值。

如果您可以通过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 

当我做这个测试（还有一些我一直在做的测试），我创建了我的自己的“上下文”堆栈对象（类似于log4net的“堆栈”实现）通过存储我的堆栈通过CallContext.LogicalSetData而不是通过CallContext.SetData（这是如何log4net存储它）。当我有多个ThreadPool线程时，我发现我的堆栈混乱了。也许是从退出子上下文时将数据合并回父上下文。我不会认为会是这种情况，因为在我的测试中，我显式地将新值输入到ThreadPool线程并在退出时弹出。基于Trace.CorrelationManager.LogicalOperationStack的实现（我写了一个抽象概念）的类似测试似乎表现正确。我想也许自动流动（向下和向后）的逻辑是占相关管理器，因为它是系统中的“已知”对象？

有些事情要在输出注：

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

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

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

注有在某些环境中的一些问题甚至CallContext.LogicalSetData：

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

Nested multithread operations tracing

（不一个问题，但一个关于Trace.CorrelationManager.ActivityId和Task Parallel Library的好帖子）：

How do Tasks in the Task Parallel Library affect ActivityID?

一个关于ASP上下文中各种“上下文”存储机制问题的博客文章。净

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

[编辑]

我发现，保持正确的上下文，而大量（或甚至不那么严重 - 我的测试中使用不同的线程/任务/并行技术执行DoLongRunningWork）使用线程可以用CallContext.LogicalSetData抛出一些数据集。

请参阅this question about using Trace.CorrelationManager.ActivityId这里StackOverflow。我发布了一个关于使用Trace.CorrelationManager.LogicalOperationStack和我的一些观察结果的答案。

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

我也贴过a very similar question on Microsoft's Parallel Extensions forum。

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

有了这样的代码模式：

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

的LogicalOperationStack的内容保持一致DoLongRunningWork是否被明确的主题/线程池线程/任务/并行（或。对于.Invoke拉开序幕）。

有了这样的代码图案：

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），它可能会被子线程/ Tasks /等成功继承。

对于这种情况发生的原因或最佳解决方法，我没有任何很好的解释。这可能是因为我测试“环境”的方式有点过分，或者可能不会。

如果你仔细研究这一点，你可以试试我在上面链接中发布的测试程序。测试程序只测试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-implementaiton：

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 
    } 

这是很多消化，但也许你会发现一些有用的！