在 Spring Boot中实现包含上下文信息的JSON日志? - zachelrath


在调试棘手的问题时,要使日志发挥作用,上下文是至关重要的。每条日志都应该始终包含与请求相关的租户、用户、订单等的关键细节。日志还必须是结构化的,以便可被日志聚合器(如DataDog、StackDriver、Kibana等)解析和搜索。
当我开始与Spring合作时,我希望实现与日志相关的两个关键目标。

  •     在与特定API请求相关的所有日志消息中自动包含关键的请求环境细节
  •     为每个API请求记录一个结构化的消息,提供关于请求(如端点、查询参数)和响应(如状态代码、持续时间)的基本细节。

具体来说:在审查日志信息时,通常会有一些与特定请求相关的关键 "上下文 "信息,这些信息最好是出现在与请求相关的每条日志信息中,但每个请求都不一样。
例如,在认证的应用程序中,在所有的日志消息中包含用户ID或租户ID(在多租户应用程序中),在试图快速诊断一个问题时非常有帮助,因为你可以找到一个给定的日志消息,抓住租户ID或用户ID,然后使用这些来搜索与该用户相关的其他错误,或检查该租户是否有一些奇怪的配置设置,等等。或者,对于内部服务,你可能有一个订单号,为了诊断处理该订单的某个步骤的问题,你想过滤你的日志,只显示与给定订单号相关的日志。
 
我感到惊讶的是,我发现描述如何在Spring Boot中具体实现这些目标的资源很少。
此应用程序提供了如何使用 Log4j2 在 Spring Boot 应用程序中进行结构化、上下文日志记录的示例。结构化的JSON格式日志如下案例:
{
  "instant" : {
   
"epochSecond" : 1636639189,
   
"nanoOfSecond" : 190833000
  },
 
"thread" : "http-nio-8080-exec-1",
 
"level" : "INFO",
 
"loggerName" : "com.zachelrath.springboot.structuredloggingdemo.OrderController",
 
"message" : "Getting items",
 
"endOfBatch" : false,
 
"loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",
 
"contextMap" : {
   
"orderNumber" : "123",
   
"retailer" : "acme"
  },
 
"threadId" : 24,
 
"threadPriority" : 5
}
{
 
"instant" : {
   
"epochSecond" : 1636639189,
   
"nanoOfSecond" : 193742000
  },
 
"thread" : "http-nio-8080-exec-1",
 
"level" : "INFO",
 
"loggerName" : "com.zachelrath.springboot.structuredloggingdemo.OrderController",
 
"message" : "Got items, returning",
 
"endOfBatch" : false,
 
"loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",
 
"contextMap" : {
   
"orderNumber" : "123",
   
"retailer" : "acme"
  },
 
"threadId" : 24,
 
"threadPriority" : 5
}

点击标题查看Github代码,主控制器位于此处:OrderController
 
运行: mvn spring-boot:run
 
为什么使用Log4j2?
如果你熟悉Spring Boot,你可能会想,既然Spring Boot使用Logback作为其日志框架,为什么还要使用Log4j2?

我不会去争论各种Java日志库的利弊,因为已经有很多其他的文章都是这样写的,但简单的答案是这样的。Log4j2的异步日志在高交易量方面大大超过了Logback,同时提供了一个开发者友好的API,相当容易使用。因此,我现在的公司已经将Log4j2标准化,用于高吞吐量的应用。

 
原理实现
Logback和Log4j2都支持一种叫做 "映射的诊断上下文"(Mapped Diagnostic Context)的功能,即MDC,每个线程都有一个字典/映射的上下文,然后你可以根据需要从中读取和写入。存储在线程的MDC中的数据可以使用%X变量进行记录。你可以记录所有的MDC,也可以只记录特定的信息,例如,如果你的日志模式包括%X{orderNumber},那么只有线程的MDC中 "orderNumber "键的值会被记录。由于每个网络请求都是由不同的线程来处理的,这就给了我们想要的东西。