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

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

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

这里有一个链接指向 documentation for NDC .

总之,效果类似于使用属性,就像在示例中一样。唯一的区别是,可以对ndc进行堆叠,以便每次在堆叠上推送值时,它都会连接到消息。它还支持using语句,这使得代码更加清晰。

更新: 2014年11月12日-见我的第一部分:

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

获取最新更新。log4net的logicalthreadcontext最近(最近几年)有所更新,因此现在可以正常工作。链接帖子中的更新提供了一些细节。

结束更新。

这里有一个可能对你有帮助的想法。部分问题在于log4net上下文对象(threadcontext和logicalthreadcontext)不会将其属性“流”到“子”线程。logicalthreadcontext给人一种错误的印象,它确实是这样,但实际上不是这样。 CallContext.SetData 存储其属性。通过set data设置的数据被附加到线程,但它不是由子线程“继承”的。因此,如果通过如下方式设置属性:

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

该属性将通过%property pattern converter进行日志记录,并且在从最初设置该属性的同一线程进行日志记录时将包含一个值,但它不会包含从该线程生成的任何子线程中的值。

如果您可以通过callContext.logicalSetData保存您的属性(请参见上面的链接),那么这些属性将“流”到(或由)任何子线程继承。所以,如果你可以这样做:

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

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

见 this blog posting by Jeffrey Richter 有关使用callContext.logicalSetData的详细信息。

您可以通过callcontext.logicalsetdata轻松地存储您自己的信息,并通过编写自己的日志来让log4net记录这些信息。 PatternLayoutConverter . 我附上了两个新的PatternLayoutConverter的一些示例代码。

第一个允许您记录存储在 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 Converter中所示)来指定要使用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存储它的方式)。我发现当我有几个线程池线程时,我的堆栈混乱了。可能是在子上下文退出时将数据合并回父上下文。我不会想到会发生这种情况,因为在我的测试中,我显式地将条目上的新值推送到线程池线程,并在退出时弹出它。使用trace.correlationmanager.logicalOperationsTack-based实现的类似测试(我在上面写了一个抽象)似乎运行正常。我想可能是自动流动(向下和向后)逻辑在解释CorrelationManager,因为它是系统中的一个“已知”对象????

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

1. trace.correlationmanager信息是通过callContext.logicalSetData存储的,因此它被“流”到子线程。测试此函数使用trace.correlationmanager.stampogicalOperation将逻辑操作(以传入的名称命名)“推送”到LogicalOperationStack。threadpool线程中的第一条logger.debug语句显示threadpool线程继承了与父线程相同的logicalOperationstack。在threadpool线程内部,我启动了一个新的逻辑操作,它被堆叠到继承的logicaloperationstack上。您可以在第二个logger.debug输出中看到结果。最后,在离开之前,我停止了逻辑操作。第三个logger.debug输出显示了这一点。

2. 从输出中可以看到,callContext.logicalSetData也“流”到子线程。在我的测试代码中,我选择在threadpool线程内的logicalsetdata中设置一个新值,然后在离开之前清除它(freenameddataslot)。

您可以自由地尝试这些模式布局转换器,看看是否可以实现您正在寻找的结果。正如我所演示的,您至少应该能够在日志输出中反映哪些线程池线程是由哪个其他线程(父线程?)启动/使用的。线程。

注意,在某些环境中,即使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的数据集出问题。

见 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

无论dolongrunningwork是由显式线程/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的内容保持一致,除非由parallel.for或parallel.invoke启动dolongrunningwork。原因似乎与以下事实有关: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
  }

要消化的东西很多,但也许你会发现其中一些有用!

根据我的POV,唯一的可能是更改模块内的线程创建,否则您就不能添加任何相关上下文。
如果您可以更改代码,那么您将创建一个从已用的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 从外部注入所需的日志记录行为。