如何使用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 
    } 

這是很多消化，但也許你會發現一些有用的！