Spring 应用程序中的日志链路追踪

2022-12-07, 星期三, 22:45

pattern: "%date{ISO8601_OFFSET_DATE_TIME_HHMM} %-5level %logger{1.}: %message%n"

如上是一个 Log4j 2 的 Pattern 配置，系统在服务多个用户时可能会产生如下日志：

2022-12-07T09:38:42,080+0800 WARN c.d.l.s.UserService: ……
2022-12-07T09:38:42,081+0800 INFO c.d.l.s.UserService: ……
2022-12-07T09:38:42,187+0800 INFO c.d.l.s.UserService: ……
2022-12-07T09:38:42,188+0800 WARN c.d.l.s.UserService: ……

日志中出现了两条 WARN，然而很难判断这两条 WARN 是否来自同一次用户请求。在 Pattern 中添加 %processId 和 %threadId 也许可以做区分：

pattern: "%date{ISO8601_OFFSET_DATE_TIME_HHMM} %-5level %logger{1.}<%processId_%threadId>: %message%n"

2022-12-07T11:04:30,820+0800 WARN c.d.l.s.UserService<9663_48>: ……
2022-12-07T11:04:30,820+0800 INFO c.d.l.s.UserService<9663_48>: ……
2022-12-07T11:04:30,820+0800 INFO c.d.l.s.UserService<9663_48>: ……
2022-12-07T11:04:30,927+0800 INFO c.d.l.s.UserService<9663_50>: ……
2022-12-07T11:04:30,927+0800 INFO c.d.l.s.UserService<9663_50>: ……

Thread ID 相同的记录可以认为是来自同一次用户请求。不过一旦涉及到异步调用，或是创建了新线程，Thread ID 也不可靠了。涉及到多个服务时，一个用户请求在多个应用程序间传递会让日志变得更加无法追踪。

这种情况下可以引入 Trace 和 Span 的概念，使用 Trace ID 和 Span ID 来做链路跟踪。用户发起的请求可以视为一个 Trace，分配一个 Trace ID。Span 的粒度要细一些，不过目前可以理解为描述一个应用程序/服务从接收请求到处理完毕返回的过程。调用下游服务时，当前服务负责分配一个新的 Span ID。

Mapped Diagnostic Context a.k.a MDC

为了非侵入式地添加日志信息，我们可以使用 MDC，可以理解成 Logger 自己的 ThreadLocal<T>。该功能已受到 SLF4J 和各主流日志后端支持。

可以使用拦截器为每个请求分配 Trace ID 和 Span ID，不过此处为了演示简易起见，直接在 Controller 方法中生成并添加 UUID。

// method in Controller
@PostMapping("/login")
public String loginOrRegister(String username) {
    MDC.put("_TRACE_", UUID.randomUUID().toString());
    MDC.put("_SPAN_", UUID.randomUUID().toString());
    // ...

// method in Service
public boolean isExist(String username) {
    boolean isExist = random.nextBoolean();
    if (isExist) {
        logger.atInfo()
                .setMessage("check if user exists")
                .log();
                // ...

PatternLayout.Pattern 中添加 %variablesNotEmpty{TRACE=%MDC{_TRACE_};SPAN=%MDC{_SPAN_}} 标记。

2022-12-07T14:59:31,387+0800 INFO  c.d.l.s.UserService TRACE=78b8f292-aa63-44e1-8785-f4156f90f8c5;SPAN=7487c826-7134-4854-9cdc-8fdc1dc5bc65 {_SPAN_=7487c826-7134-4854-9cdc-8fdc1dc5bc65, _TRACE_=78b8f292-aa63-44e1-8785-f4156f90f8c5}: check if user exists

除了日志追踪，MDC 还可用于添加 User ID，Biz ID 等业务上可用于聚合分析的数据。

SLF4J API 2.x 新增的 org.slf4j.Logger::addKeyValue 方法可以在日志中增加键值对，使用 Log4j 2 作为日志后端时，也会被 %MDC 识别和输出。

Spring Cloud Sleuth

Spring Cloud Sleuth 是一个分布式系统请求追踪工具，不过也可作用于单体系统。为项目添加 org.springframework.cloud:spring-cloud-starter-sleuth 依赖后，MDC 中会自动增加 traceId 和 spanId 变量。一般情况下第一个 Span 的 ID 与 Trace ID 相同。

2022-12-07T18:47:41,261+0800 INFO [loggingShowcase,1a967a768513c467,1a967a768513c467] c.d.l.s.UserService {spanId=1a967a768513c467, traceId=1a967a768513c467}: user login

Java 代码中可以通过注入 org.springframework.cloud.sleuth.Tracer tracer 并调用 tracer.currentSpan().context().traceId() 获取 Trace ID（类似地，还有其他上下文信息）。可以默认在响应头中返回追踪信息，也可以只在发生异常时通过 ProblemDetail 返回。

Spring Cloud Sleuth 通过请求头中的键值对传递链路追踪信息，spring.sleuth.propagation.type 属性支持配置一个逗号分隔的列表，默认为 B3，在请求头中使用 4 个参数：X-B3-TraceId, X-B3-SpanId, X-B3-ParentSpanId 和 X-B3-Sampled。

使用 Spring Cloud Sleuth 的服务通过读取 X-B3-TraceId 和 X-B3-SpanId 接收上游传递的链路追踪信息。向下游发起请求时，如果使用的 Web Client 是一个 Spring Bean，就会触发 Span 更新，并把追踪信息传播到下一跳。

@Resource
private RestTemplateBuilder restTemplateBuilder;

@GetMapping("/another-service/autowired-rest-template-builder")
public void service_1_1() {
    logger.atInfo().log("upstream call");
    restTemplateBuilder.build().getForObject("http://localhost:8888/", String.class);
    logger.atInfo().log("invoke downstream");
}

如下脚本将在 8888 端口上持续监听 HTTP 请求并打印到控制台。

while true; do { echo -e 'HTTP/1.1 200 OK\r\n'; } | nc -l 8888; echo '\r\n'; done

使用 curl 'http://localhost:8080/another-service/autowired-rest-template-builder' -H 'X-B3-TraceId: d0cbb2c1c0ebc242' -H 'X-B3-SpanId: d0cbb2c1c0ebc242' 发送请求，可以看到应用在调用下游服务时传递的链路追踪信息。

GET / HTTP/1.1
Accept: text/plain, application/json, application/*+json, */*
X-B3-TraceId: d0cbb2c1c0ebc242
X-B3-SpanId: c40700c1169949c9
X-B3-ParentSpanId: d0cbb2c1c0ebc242
X-B3-Sampled: 0
User-Agent: Java/17.0.5
Host: localhost:8888
Connection: keep-alive