背景
在日志记录时,我们往往希望体现出一条清晰的操作线索,先执行了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 小小的一件事,如果不是多一点心眼,多思考一下,可能就会忽略掉某些情况,导致后续被测试或者生产中采集不到数据时才发现,就不值得了。