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

11

我正在尝试找到一种方法,从一堆线程中记录有用的上下文。问题在于很多代码都是在通过线程池线程传递的事件上处理的(据我所知),因此它们的名称与任何上下文都没有关系。以下代码可以演示这个问题:

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答案的评论/问题。 - wageoghe
4个回答

17

更新: 2014年12月11日 - 请参阅我在此处发布的第一部分内容:

log4net.ThreadContext和log4net.LogicalThreadContext之间有什么区别?

最近(在过去的几年中),Log4Net的LogicalThreadContext已经进行了更新,以便它现在可以正常工作。链接帖子中的更新提供了一些详细信息。

END UPDATE.

这里有一个可能会对您有所帮助的想法。问题的一部分是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的更多信息,请参见这篇Jeffrey Richter的博客文章

通过编写自己的PatternLayoutConverter,您可以轻松地通过CallContext.LogicalSetData存储自己的信息,并使其可供log4net记录。我已附上两个新PatternLayoutConverters的示例代码。

第一个允许您记录存储在Trace.CorrelationManagerLogicalOperationStack中的信息。布局转换器允许您记录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存储它的方式)。我发现当我有几个线程池线程时,我的堆栈变得混乱了。也许是因为当子上下文退出时将数据合并回父上下文导致的。我本不认为会是这样,在我的测试中,我明确地将新值推入线程池线程并在退出时将其弹出。使用基于Trace.CorrelationManager.LogicalOperationStack的实现进行类似的测试(我编写了一个抽象层),似乎表现正确。我猜可能是自动流动(向下和向上)逻辑考虑到了CorrelationManager,因为它是系统中“已知”的对象吗???
输出中需要注意的一些事项:
  1. Trace.CorrelationManager信息通过CallContext.LogicalSetData存储,因此会"流动"到子线程中。TestThis使用Trace.CorrelationManager.StartLogicalOperation将一个逻辑操作(以传入的名称命名)"推送"到LogicalOperationStack上。线程池线程中的第一个logger.Debug语句显示线程池线程继承了与父线程相同的LogicalOperationStack。在线程池线程内部,我启动了一个新的逻辑操作,它被堆叠在继承的LogicalOperationStack上。您可以在第二个logger.Debug输出中看到其结果。最后,在离开之前,我停止了逻辑操作。第三个logger.Debug输出显示了这一点。

  2. 从输出中可以看出,CallContext.LogicalSetData也会"流动"到子线程中。在我的测试代码中,我选择在线程池线程中设置一个新值,并在离开之前清除它(FreeNamedDataSlot)。

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

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

"子"逻辑数据会合并到"父"逻辑数据中: EndInvoke更改当前CallContext-为什么?

嵌套的多线程操作跟踪

(这不是一个问题,而是一篇关于Trace.CorrelationManager.ActivityId和Task Parallel Library的好文章):

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

关于ASP.Net上下文存储机制问题的一个经常链接的博客文章。

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

[编辑]

我发现在使用线程(可能甚至不是很重)时,保持正确的上下文可能会使一些使用CallContext.LogicalSetData的数据集出现问题。

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

后来我使用了那个问题的答案作为在线程/任务/并行的上下文中使用Trace.CorrelationManager.LogicalOperationStack的基础提出了自己的问题。

我还在Microsoft的Parallel Extensions论坛上发布了一个非常相似的问题

您可以阅读这些帖子以查看我的观察结果。简要总结如下:

使用以下代码模式:

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

无论是由显式线程/线程池线程/任务/Parallel(.For或.Invoke)启动DoLongRunningWork,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 使用主线程作为执行并行操作的线程之一有关。
这意味着,如果您想将整个并行化(或线程化)操作作为单个逻辑操作封闭,并将每次迭代(即每次委托调用)作为外部操作中嵌套的逻辑操作,请测试过的大多数技术(Thread/ThreadPool/Task)都能正常工作。在每次迭代中,LogicalOperationStack 反映出有一个外部任务(针对主线程)和一个内部任务(即委托)。
如果使用 Parallel.For 或 Parallel.Invoke,则 LogicalOperationStack 不会正常工作。在上面链接的帖子中的示例代码中,LogicalOperationStack 永远不应该有超过 2 个条目。一个是主线程,另一个是委托。但是,使用 Parallel.For 或 Parallel.Invoke 后,LogicalOperationStack 最终将拥有比 2 个更多的条目。
通过使用 CallContext.LogicalSetData 进行存储(如果尝试通过存储具有 LogicalSetData 的 Stack 来模拟 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的实现:

  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
@我的另一个自己 - 自从我第一次发布这个答案以来,我添加了更多关于我所学的细节。 它可能对你有用,也可能没有。 - wageoghe

2

log4net中的上下文信息是每个线程独立的,因此每次启动新线程时都需要将上下文信息添加到其中。您可以使用属性或NDC来实现。NDC也是每个线程独立的,因此您仍然需要在某个时刻将其添加到每个线程的上下文中,这可能是您想要的,也可能不是。但这样做可以避免将其添加到消息本身中。在您的示例中,可以像这样:

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

这里是NDC文档链接

总的来说,效果类似于使用属性,就像你的示例中所示。唯一的区别是NDC可以堆叠,每次将值推送到堆栈上时,都会将其连接到消息中。它还支持使用语句,使代码更清晰。


1
谢谢,但我想避免需要在每个绑定事件的开始处执行某些操作。我希望有一种方法可以在线程创建时仅设置线程名称或上下文,然后无需再担心它。 - My Other Me
根据此链接http://logging.apache.org/log4net/release/sdk/log4net.NDC.html,NDC已被弃用。 - Stefan Egli
虽然这不是解决我的问题的最终方案,但它让我找到了一些可行的方法。 - My Other Me
@My Other Me - 我看到你最近的评论,知道你已经想出了一些可行的解决方案。我很好奇你最终是如何解决这个问题的。如果你有时间,能否简要描述一下你所做的事情,或者提供一些代码示例(比如你如何调用log4net和/或操作NDC)?谢谢。 - wageoghe
@wageoghe:(希望你能看到这个消息)我们在想要实现的功能上遇到了瓶颈。我们意识到给工作线程命名是不好的,因为这个名字会出现在应用程序的其他地方,会造成很大的混乱。最后我找到了一个解决方案,就是将所需的线程名称存储在接收事件的类实例中,在事件到达时设置线程名称,在退出时取消设置。但我仍在寻找更加优雅的解决方案。 - My Other Me
@My Other Me - 你可能已经通过SO收到了通知,但为了确保,我正在向你的StackExchange收件箱发送消息。我发布了一个新答案,展示了如何获得更好的日志记录结果。不知道是否有帮助。 - wageoghe

0

一个选择是,不使用单个静态记录器实例,而是通过使用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来外部注入所需的日志记录行为。


1
字段初始化程序不会在每个线程上单独调用,因此不应与“ThreadStatic”一起使用。 - Vlad
@Vlad,你发现得真好。确实,MSDN说:“不要为标记有ThreadStaticAttribute的字段指定初始值,因为这样的初始化仅在类构造函数执行时发生一次,因此仅影响一个线程。” 我通过添加静态属性getter来初始化该字段来纠正了错误。 - hemp

0

从我的角度来看,唯一的可能性就是更改模块内部的线程创建方式,否则你无法添加任何相关上下文。
如果您可以更改代码,则可以创建一个类,该类将继承所使用的 System.Threading 类(例如您的示例中的 Thread),并调用超类并添加相关的日志上下文。
还有一些其他技巧可能可行,但这将是一种干净的方法,没有任何不良手段。


网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接