bigywater.tech
Spring · 53

请求日志与 MDC:每个请求带 trace id

怎么让每个请求的日志都带同一个 trace id?为什么 @Async 和 CompletableFuture 里的日志没有 id?Callable 的日志呢?忘了清 MDC 会怎样?CommonsRequestLoggingFilter 打出来的日志安全吗?这篇在 Spring Boot 4.0.8 上逐个把线程名和 MDC 打印出来。

0 / 4
装了 TaskDecorator 之后,supplyAsync、new Thread、ASYNC 派发里带 id 的日志条数——仍然没有
2 / 2
没带 X-Request-Id 的请求里,日志却带着上一个请求 id 的个数(Filter 没清 MDC)
明文
includeHeaders=true 时 Authorization 和 Cookie 在日志里的样子

基本做法

实测 · 本机执行输出 
  GET /work  [X-Request-Id: req-A] → 200,响应头 X-Request-Id = req-A
      [http-nio-9601-exec-2] traceId=[req-A] Main: controller 开始
      [http-nio-9601-exec-2] traceId=[req-A] Svc: service 处理中
      [http-nio-9601-exec-2] traceId=[req-A] Main: controller 结束
  GET /work → 200,响应头 X-Request-Id = gen-1
      [http-nio-9601-exec-3] traceId=[gen-1] Main: controller 开始
      [http-nio-9601-exec-3] traceId=[gen-1] Svc: service 处理中
      [http-nio-9601-exec-3] traceId=[gen-1] Main: controller 结束
  GET /work  [X-Request-Id: req-B] → 200,响应头 X-Request-Id = req-B
      [http-nio-9601-exec-5] traceId=[req-B] Main: controller 开始
      [http-nio-9601-exec-5] traceId=[req-B] Svc: service 处理中
      [http-nio-9601-exec-5] traceId=[req-B] Main: controller 结束

最靠前的 Filter 设置 MDC,日志格式里用 %X{traceId},业务代码不用传参数。

换线程

实测 · 本机执行输出 
  GET /async-plain  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9602-exec-2] traceId=[req-T] Main: controller 调用 @Async
      [task-1] traceId=[] Svc: @Async 方法里
  GET /cf  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9602-exec-3] traceId=[req-T] Main: controller 调用 CompletableFuture.supplyAsync
      [ForkJoinPool.commonPool-worker-1] traceId=[] Main: supplyAsync 里(公共 ForkJoinPool)
  GET /new-thread  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9602-exec-5] traceId=[req-T] Main: controller 开新线程
      [raw-thread] traceId=[] Main: new Thread 里
  GET /callable  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9602-exec-7] traceId=[req-T] Ic: 拦截器 preHandle [REQUEST]
      [http-nio-9602-exec-7] traceId=[req-T] Main: controller 返回 Callable
      [task-2] traceId=[] Main: Callable 里
      [http-nio-9602-exec-8] traceId=[] Ic: 拦截器 preHandle [ASYNC]
      [http-nio-9602-exec-8] traceId=[] Ic: 拦截器 afterCompletion [ASYNC]

MDC 是线程局部的,@Async、Callable、CompletableFuture、new Thread 里都是空。

TaskDecorator

实测 · 本机执行输出 
  GET /async-plain  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9603-exec-2] traceId=[req-T] Main: controller 调用 @Async
      [task-1] traceId=[req-T] Svc: @Async 方法里
  GET /cf  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9603-exec-3] traceId=[req-T] Main: controller 调用 CompletableFuture.supplyAsync
      [ForkJoinPool.commonPool-worker-1] traceId=[] Main: supplyAsync 里(公共 ForkJoinPool)
  GET /new-thread  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9603-exec-5] traceId=[req-T] Main: controller 开新线程
      [raw-thread] traceId=[] Main: new Thread 里
  GET /callable  [X-Request-Id: req-T] → 200,响应头 X-Request-Id = req-T
      [http-nio-9603-exec-7] traceId=[req-T] Ic: 拦截器 preHandle [REQUEST]
      [http-nio-9603-exec-7] traceId=[req-T] Main: controller 返回 Callable
      [task-2] traceId=[req-T] Main: Callable 里
      [http-nio-9603-exec-8] traceId=[] Ic: 拦截器 preHandle [ASYNC]
      [http-nio-9603-exec-8] traceId=[] Ic: 拦截器 afterCompletion [ASYNC]

只对 Spring 自己的执行器生效,别的线程要自己传递。

泄漏

实测 · 本机执行输出 
  GET /plain  [X-Request-Id: req-LEAK] → 200,响应头 X-Request-Id = req-LEAK
      [http-nio-9604-exec-1] traceId=[req-LEAK] Main: controller 开始(没有带 X-Request-Id)
  GET /plain → 200,响应头 X-Request-Id = None
      [http-nio-9604-exec-1] traceId=[req-LEAK] Main: controller 开始(没有带 X-Request-Id)
  GET /plain → 200,响应头 X-Request-Id = None
      [http-nio-9604-exec-1] traceId=[req-LEAK] Main: controller 开始(没有带 X-Request-Id)

不清 MDC,线程复用会让下一个请求继承上一个的 id。

请求日志

实测 · 本机执行输出 
  POST /post?x=1&y=2  [X-Request-Id: req-R, Authorization: Bearer SECRET-TOKEN-123] → 200,响应头 X-Request-Id = req-R
      [http-nio-9605-exec-2] traceId=[req-R] CommonsRequestLoggingFilter: Before request [POST /post?x=1&y=2]
      [http-nio-9605-exec-2] traceId=[req-R] Main: controller 收到 body 长度 84
      [http-nio-9605-exec-2] traceId=[req-R] CommonsRequestLoggingFilter: After request [POST /post?x=1&y=2, payload={"name":"Tom","note":"zzzzzzzz]

payload 只在 After request 出现并被截断。

敏感头

实测 · 本机执行输出 
  POST /post?x=1  [X-Request-Id: req-R, Authorization: Bearer SECRET-TOKEN-123, Cookie: sid=abc] → 200,响应头 X-Request-Id = req-R
      [http-nio-9606-exec-2] traceId=[req-R] CommonsRequestLoggingFilter: Before request [POST /post?x=1, client=127.0.0.1, headers=[Host:"127.0.0.1:9606", Accept-Encoding:"identity", Content-Length:"7", X-Request-Id:"req-R", Authorization:"Bearer SECRET-TOKEN-123", Cookie:"sid=abc", Content-Type:"application/json;charset=UTF-8"]]
      [http-nio-9606-exec-2] traceId=[req-R] Main: controller 收到 body 长度 7
      [http-nio-9606-exec-2] traceId=[req-R] CommonsRequestLoggingFilter: After request [POST /post?x=1, client=127.0.0.1, headers=[Host:"127.0.0.1:9606", Accept-Encoding:"identity", Content-Length:"7", X-Request-Id:"req-R", Authorization:"Bearer SECRET-TOKEN-123", Cookie:"sid=abc", Content-Type:"application/json;charset=UTF-8"], payload={"a":1}]

includeHeaders 会把凭据原样写进日志。

遮蔽

实测 · 本机执行输出 
  POST /post?x=1  [X-Request-Id: req-R, Authorization: Bearer SECRET-TOKEN-123, Cookie: sid=abc] → 200,响应头 X-Request-Id = req-R
      [http-nio-9607-exec-2] traceId=[req-R] CommonsRequestLoggingFilter: Before request [POST /post?x=1, headers=[Host:"127.0.0.1:9607", Accept-Encoding:"identity", Content-Length:"7", X-Request-Id:"req-R", Cookie:"sid=abc", Content-Type:"application/json;charset=UTF-8", Authorization:"masked"]]
      [http-nio-9607-exec-2] traceId=[req-R] Main: controller 收到 body 长度 7
      [http-nio-9607-exec-2] traceId=[req-R] CommonsRequestLoggingFilter: After request [POST /post?x=1, headers=[Host:"127.0.0.1:9607", Accept-Encoding:"identity", Content-Length:"7", X-Request-Id:"req-R", Cookie:"sid=abc", Content-Type:"application/json;charset=UTF-8", Authorization:"masked"], payload={"a":1}]

headerPredicate 只遮蔽指定的头,别的敏感头要自己考虑。

分步演示

请求日志与 MDC
本步的对象

    本文用到的工具与边界

    • 本机 macOS 27 arm64 / OpenJDK 21.0.12(Homebrew) / Spring Boot 4.0.8(Spring Framework 7.0.9、Tomcat 11.0.24) / Spring Cloud 2025.1.3;用 javac 编译、java 直接运行,依赖由 Maven 从 Maven Central 解析;数字每次运行会有小幅抖动。用 Spring Boot 4.0.8 的 SpringApplication(spring-boot-starter-webmvc,内嵌 Tomcat 11.0.24,日志用 Logback,格式含 %X{traceId});请求由 Python http.client 发出;每个场景(是否有 TaskDecorator、是否清 MDC、请求日志选项)分别启动应用;第四节把 Tomcat 线程数限制为 1 来保证线程复用
    • 没有验证:Micrometer Tracing / Observation 自动带 traceId 的方式(见第 86 篇);虚拟线程下的 MDC;Reactor 的 Context 与 MDC(见第 62 篇);ThreadLocal 继承(InheritableThreadLocal、ScopedValue);Tomcat access log 里带 X-Request-Id;结构化日志(JSON)输出;DeferredResult 回调线程的 MDC
    京ICP备2026067502号-1京公网安备11010502063487号