开发专栏
log4net 的 MDC、NDC、ThreadContext 和 LogicalThreadContext
2020-02-15 16:16 ( 1 年前 )
1247
log4net 开发随记 异步

看似简单的 MDC 记录请求 Id 并打印到日志中的任务竟暗藏杀机。NDC、ThreadContext、LogicalThreadContext 究竟是何方妖孽?欢迎阅读今天的开发随记😂

背景

在日志记录时,我们往往希望体现出一条清晰的操作线索,先执行了A,然后执行了B,接着执行C……但在 Web 项目中,往往同时处理着多个不同客户端发出的请求,如果这些请求都在进行相同的操作,我们的日志将无法分辨。项目中使用的日志框架是 log4net,过去,我在项目中通过 AutoFac 创建了一个生命周期为 PreRequest 的对象,内部维护了一个 GUID,用来充当 RequestId。这样在记录日志时将该 RequestId 一同记录上,就解决了该问题。

后来领导给其他小组提到了 log4net 的 MDC,希望我们也进行调整,大概意思是可以用 MDC 储存 RequestId 并能方便的生成到日志中。本文记录了这次修改的过程。

MDC

说实话,学艺不精的我从没注意过 log4net 的命名空间下还有这么一个类……根据同事提供的代码,很快就完成了这一修改。首先在收到请求后,生成一个 GUID 给 MDC,并在响应生成后移除。以 ASP.NET MVC 为例:

const string REQUEST_ID_KEY = "RequestId";

protected void Application_BeginRequest()
{
    MDC.Set(REQUEST_ID_KEY, Guid.NewGuid().ToString());
}

protected void Application_EndRequest()
{
    MDC.Remove(REQUEST_ID_KEY);
}

并且修改 log4net 配置中 appenderlayout,将 RequestId 的占位符 [%property{RequestId}] 加入:

<layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date [%5level] [%property{RequestId}] %logger - %message%newline"/>
</layout>

用一个非常简单的 Action 测试效果:

static readonly ILog _logger = LogManager.GetLogger(typeof(HomeController));

public ActionResult Index()
{
    _logger.Info("Do something");

    return View("Index");
}

日志中的内容和预期的一样:

2020-02-15 22:22:37,453 [INFO ] [c91811c5-8e86-4e27-95a8-b90e541c077a] Log4NetMDCTest.Controllers.HomeController - Do something

好了,搞定了,还没什么看头,散了散了。

且慢,好歹先看看 MDC 是啥吧。

MDC 是什么

F12 看了一下 log4net.MDC 类:

//
// 摘要:
//     Implementation of Mapped Diagnostic Contexts.
//
// 言论:
//     The MDC is deprecated and has been replaced by the log4net.ThreadContext.Properties.
//     The current MDC implementation forwards to the ThreadContext.Properties.
//     The MDC class is similar to the log4net.NDC class except that it is based on
//     a map instead of a stack. It provides mapped diagnostic contexts. A Mapped Diagnostic
//     Context, or MDC in short, is an instrument for distinguishing interleaved log
//     output from different sources. Log output is typically interleaved when a server
//     handles multiple clients near-simultaneously.
//     The MDC is managed on a per thread basis.

几个重要的信息:

  1. 它是映射诊断上下文的实现
  2. MDC 已被弃用,当前 MDC 被转发到了 ThreadContext.Properties
  3. 它和 NDC 类似,区别在于 MDC 通过映射来记录上下文,NDC 通过栈来记录

说明 MDC 可以从程序中储存上下文信息,并在 log 中使用,另外 MDC 已经变成了 ThreadContext.Propertie,那这又是啥,NDC 又是啥?

NDC

伴着好奇心,F12 看看 log4net.NDC 类:

    //
    // 摘要:
    //     Implementation of Nested Diagnostic Contexts.
    //
    // 言论:
    //     The NDC is deprecated and has been replaced by the log4net.ThreadContext.Stacks.
    //     The current NDC implementation forwards to the ThreadContext.Stacks["NDC"].
    //     A Nested Diagnostic Context, or NDC in short, is an instrument to distinguish
    //     interleaved log output from different sources. Log output is typically interleaved
    //     when a server handles multiple clients near-simultaneously.
    //     Interleaved log output can still be meaningful if each log entry from different
    //     contexts had a distinctive stamp. This is where NDCs come into play.
    //     Note that NDCs are managed on a per thread basis. The NDC class is made up of
    //     static methods that operate on the context of the calling thread.

和 MDC 的几乎如出一辙,几点重要的信息:

  1. 嵌套诊断上下文的实现
  2. NDC 已被弃用,当前 NDC 被转发到了 ThreadContext.Stacks["NDC"]

先来试试 NDC 的 API 吧,和栈一样提供了 Push()Pop()。而 Push() 方法必须传入一个 string 类型的参数,因此可以看来它不像 MDC 可以自己设置 Key。

protected void Application_BeginRequest()
{
    NDC.Push(Guid.NewGuid().ToString());
}

同样,要在日志中记录 NDC 的内容,需要增加 %x 占位符:

<layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date [%5level] %x %logger - %message%newline"/>
</layout>

日志的效果:

2020-02-15 23:05:40,143 [INFO ] 5eea4302-868e-4f3e-b549-2eaa358bf9e9 Log4NetMDCTest.Controllers.HomeController - Do something

如果 Push() 多次呢?

protected void Application_BeginRequest()
{
    NDC.Push(Guid.NewGuid().ToString());
    NDC.Push("test");
}

会这样:

2020-02-15 23:06:51,929 [INFO ] 4540fc08-e530-4907-8fc6-5c9700acb93a test Log4NetMDCTest.Controllers.HomeController - Do something

难怪是 NDC (Nested 嵌套),多次 Push() 的内容会拼接在一起输出到日志中。

NDC 与 MDC 的区别

通过上面的测试以及在网上搜索,结合 StackOverflow 这篇帖子 What is the difference between Log4j's NDC and MDC facilities? 可以知道:

  • NDC 的 N 表示嵌套,即推送多个值到栈中,日志中会将它们组合起来打印
  • MDC 的 M 表示映射(mapped),值通过 key/value 的形式来储存,日志中也需要指定 key 才能进行输出

简而言之,如果只有一个值或者可以接受嵌套输出,那么 NDC 就能满足;如果要分别管理多个不同 key 的值,应该使用 MDC

ThreadContext

在看 MDC 时了解到,MDC 已经转发到了 ThreadContext.Properties 上,其实效果是一样的(它俩是一个东西),只是写法上的差异:

const string REQUEST_ID_KEY = "RequestId";

protected void Application_BeginRequest()
{
    ThreadContext.Properties[REQUEST_ID_KEY] = Guid.NewGuid().ToString();
}

protected void Application_EndRequest()
{
    ThreadContext.Properties.Remove(REQUEST_ID_KEY);
}

log4net 的配置文件中,也是使用 [%property{RequestId}] 占位符。

MDC 和 ThreadContext 的问题

当看到 MDC 被转发到 ThreadContext.Properties 时,我其实是警觉的,因为从这个名字来看,它和 Thread 有关系。我们的程序中有一部分代码是异步(Async)的。我们都知道 C## 中,当 await 一个异步操作后,后续代码有可能会交由另一个线程来进行,也就是说 await 前后是不同的线程在干活儿,ThreadContext.Properties 会不会出现问题?

将前面同步写法的 Index Action 修改为异步的,并把线程 Id 记录到 log 中:

public async Task<ActionResult> Index()
{
    _logger.Info(Thread.CurrentThread.ManagedThreadId);

    await Task.Delay(1000);

    _logger.Info(Thread.CurrentThread.ManagedThreadId);

    return View();
}

也可以使用 log4net 的 %t 占位符来记录线程号,修改一下 layout

<layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date [%-5level] [%property{RequestId}] [%t] %logger - %message%newline"/>
</layout>

日志的效果:

2020-02-15 23:34:46,819 [INFO ] [58703841-ab2e-43fb-bf73-5c9b0c4c92db] [8] Log4NetMDCTest.Controllers.HomeController - 8
2020-02-15 23:34:47,821 [INFO ] [(null)] [49] Log4NetMDCTest.Controllers.HomeController - 49

可以看到,await 前的线程号是 8,而 await 之后变成了 49,并且如同我担心的,await 后的 RequesId 没有被正确的记录下来,变成了 null。

LogicalThreadContext

又通过一番查询,了解到 log4net 中还有一个类叫做 LogicalThreadContext,来 F12 看看它的描述:

    //
    // 摘要:
    //     The log4net Logical Thread Context.
    //
    // 言论:
    //     The LogicalThreadContext provides a location for System.Runtime.Remoting.Messaging.CallContext
    //     specific debugging information to be stored. The LogicalThreadContext properties
    //     override any log4net.ThreadContext or log4net.GlobalContext properties with the
    //     same name.
    //     For .NET Standard 1.3 this class uses System.Threading.AsyncLocal rather than
    //     System.Runtime.Remoting.Messaging.CallContext.
    //     The Logical Thread Context has a properties map and a stack. The properties and
    //     stack can be included in the output of log messages. The log4net.Layout.PatternLayout
    //     supports selecting and outputting these properties.
    //     The Logical Thread Context provides a diagnostic context for the current call
    //     context. This is an instrument for distinguishing interleaved log output from
    //     different sources. Log output is typically interleaved when a server handles
    //     multiple clients near-simultaneously.
    //     The Logical Thread Context is managed on a per System.Runtime.Remoting.Messaging.CallContext
    //     basis.
    //     The System.Runtime.Remoting.Messaging.CallContext requires a link time System.Security.Permissions.SecurityPermission
    //     for the System.Security.Permissions.SecurityPermissionFlag.Infrastructure. If
    //     the calling code does not have this permission then this context will be disabled.
    //     It will not store any property values set on it.

LogicalThreadContext 通过 System.Runtime.Remoting.Messaging.CallContext(.NET Standard 1.3+ 为 System.Threading.AsyncLocal)来储存跨线程的上下文,这样当 await 之后,工作的线程发生了变化也不会出现问题了。

代码中只需要简单的将原本调用 ThreadContext 的地方改为 LogicalThreadContext 即可:

const string REQUEST_ID_KEY = "RequestId";

protected void Application_BeginRequest()
{
    LogicalThreadContext.Properties[REQUEST_ID_KEY] = Guid.NewGuid().ToString();
}

protected void Application_EndRequest()
{
    LogicalThreadContext.Properties.Remove(REQUEST_ID_KEY);
}

再通过异步版本的 Index Action 测试,生成的 log 如下:

2020-02-15 23:56:51,063 [INFO ] [bd64e999-c119-481b-9ecf-ca7c2cfecca0] [51] Log4NetMDCTest.Controllers.HomeController - 51
2020-02-15 23:56:52,065 [INFO ] [bd64e999-c119-481b-9ecf-ca7c2cfecca0] [35] Log4NetMDCTest.Controllers.HomeController - 35

已经如期工作了。

再提一下 NDC

前面我们了解到 NDC 其实现在相当于 ThreadContext.Stacks["NDC"]ThreadContext.Properties 在异步情况下有问题,经过测试 ThreadContext.Stacks["NDC"] 也一样存在问题,不过也可以通过 LogicalThreadContext.Stacks["NDC"] 来解决。

别看这改 MDC 小小的一件事,如果不是多一点心眼,多思考一下,可能就会忽略掉某些情况,导致后续被测试或者生产中采集不到数据时才发现,就不值得了。

许可协议

知识共享许可协议:署名-非商业性使用-禁止演绎
log4net 的 MDC、NDC、ThreadContext 和 LogicalThreadContext huhubun 采用 知识共享 署名-非商业性使用-禁止演绎 4.0 国际 许可协议 进行许可。
基于 https://bun.plus/posts/log4net-mdc-ndc-threadcontext-logicalthreadcontext 上的作品创作。