log4net 的 MDC、NDC、ThreadContext 和 LogicalThreadContext

开发专栏

4 年前

3432

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 配置中 appender 的 layout，将 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.

几个重要的信息：

它是映射诊断上下文的实现
MDC 已被弃用，当前 MDC 被转发到了 ThreadContext.Properties 上
它和 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 的几乎如出一辙，几点重要的信息：

嵌套诊断上下文的实现
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 小小的一件事，如果不是多一点心眼，多思考一下，可能就会忽略掉某些情况，导致后续被测试或者生产中采集不到数据时才发现，就不值得了。

CC BY-NC-ND

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