Spring Boot 4 中 Logbook 4 异步响应日志缺少 trace-id,如何修复?
结论
应重点检查 Logbook 的 Servlet 异步完成回调。记录响应日志时,原请求的 tracing context 可能已经不在当前线程上。将 Mono<T> 换成 CompletableFuture<T>,仍会经过这条共同的 Servlet 回调路径。
一种修复方式是升级到提供 AsyncOnCompleteListenerWrapper 扩展点的 Logbook 版本,在注册回调时捕获上下文,并在执行回调时恢复。Logbook 4.2.0 的发布记录已包含该扩展点。由于默认实现不恢复上下文,升级后还需要配置 wrapper。Logbook 发布记录、扩展点说明
现有材料不足以认定这是 Micrometer Tracing 或 Spring Boot 某一版本的回归,也不能仅凭日志缺少 trace-id 判断整个 trace 没有生成。
为什么已有配置没有解决问题?
Logbook 4.0.4 的 LogbookFilter 检测到异步请求后,会直接注册 LogbookAsyncListener,通过完成回调写出响应日志。这段代码没有包裹 Micrometer 的上下文捕获与恢复逻辑。Logbook 4.0.4 源码
需要分别检查请求处理线程、异步业务执行位置,以及最终写响应日志的完成回调。业务代码能拿到 trace-id,不代表完成回调也能拿到。
问题中尝试的两种配置作用范围不同:
ContextPropagatingTaskDecorator包装交给相应TaskExecutor执行的任务。即便装饰器已经应用到执行器,也不会因此自动包装 Servlet 容器调用的所有AsyncListener回调。Spring API 文档Hooks.enableAutomaticContextPropagation()针对 Reactor 中的上下文传播,不能据此推断 Servlet 完成回调也会恢复上下文。改用CompletableFuture<T>后问题仍然复现,也提示需要检查共同的 Servlet 完成阶段。
Spring MVC 支持 controller 返回 Mono,并将这类单值异步结果适配为类似 DeferredResult 的处理方式。这并不意味着应用使用了 WebFlux 服务端栈。Spring MVC 异步处理文档
此处实际使用的是 jakarta.servlet.AsyncListener,原问题中的 javax.servlet.AsyncListener 是旧命名空间。Logbook 4.0.4 的 Servlet 实现使用 jakarta.servlet。
升级后如何配置上下文恢复?
先将相关 Logbook 模块统一升级到 4.2.0,并检查该版本与现有配置的兼容性。如果使用 logbook-spring-boot-starter,可以声明以下 bean:
import io.micrometer.context.ContextRegistry;
import io.micrometer.context.ContextSnapshot;
import io.micrometer.context.ContextSnapshotFactory;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.zalando.logbook.servlet.AsyncOnCompleteListenerWrapper;
@Configuration(proxyBeanMethods = false)
public class LogbookTracingConfiguration {
@Bean
AsyncOnCompleteListenerWrapper tracingCompletionWrapper() {
ContextSnapshotFactory snapshots = ContextSnapshotFactory.builder()
.contextRegistry(ContextRegistry.getInstance())
.build();
return completion -> {
ContextSnapshot captured = snapshots.captureAll();
return asyncEvent -> {
try (ContextSnapshot.Scope restored = captured.setThreadLocals()) {
completion.onComplete(asyncEvent);
}
};
};
}
}
captureAll() 必须在注册回调时执行,setThreadLocals() 必须覆盖实际写日志的回调。不能等进入 onComplete 后才捕获上下文,因为那时原请求的上下文可能已经不可见。
try-with-resources 会在回调结束后恢复线程原有的 ThreadLocal 状态,避免复用线程时残留其他请求的上下文。这是 Micrometer Context Propagation 支持的使用方式。Micrometer 示例
该示例有以下前提:
- classpath 中包含
io.micrometer:context-propagation。缺少时应使用 Spring Boot 管理的兼容版本补充依赖。 - 所用
ContextRegistry已注册需要传播的 tracing/observation 对应的ThreadLocalAccessor。 - wrapper 捕获快照时,当前线程仍处于原请求的 tracing scope 内。快照无法捕获已经退出的上下文。
Spring Boot starter 会将这个 wrapper bean 应用于 logbookFilter 和 secureLogbookFilter。如果应用手工创建过滤器,需要在创建时显式调用 withAsyncOnCompleteListenerWrapper(wrapper)。Logbook 配置说明
必须保留 Logbook 4.0.4 时怎么办?
4.0.4 没有上述扩展点,不能直接复制新版 bean 配置。该版本的 LogbookFilter 是 final 类,也无法通过继承覆盖回调注册逻辑。
如果暂时无法升级,可以维护一个基于 4.0.4 实现的自定义过滤器,在原有的监听器注册位置增加以下逻辑:
- 注册监听器前捕获当前请求的
ContextSnapshot。 - 在完成回调中打开 snapshot scope。
- 在 scope 内调用原有的响应写日志逻辑,结束后关闭 scope。
这需要替换实际生效的原过滤器注册,并保留原实现对请求包装、异步分派和响应写出的处理,避免重复记录或遗漏日志。项目的相关 issue 也说明了旧版本缺少此扩展点的限制。Logbook issue #2283
如何确认修复位置正确?
建议通过真实 Servlet 容器发起一次异步请求,比较 controller 执行时、wrapper 捕获快照时,以及完成回调恢复前后的 Tracer.currentSpan() 和 MDC.get("traceId")。
- 如果捕获快照时
currentSpan()就为空,应检查 tracing 是否启用,以及过滤器顺序是否让 Logbook 的捕获位置处于 tracing scope 内。 - 如果捕获时有 span、恢复后没有,应检查使用的
ContextRegistry和已注册的 accessor。 - 如果恢复后 span 存在,但日志仍没有 trace-id,应继续检查 MDC 关联和日志格式。日志展示字段可能叫
trace-id,而 MDC 键通常是traceId,两者需要对应。
仅有 controller 单元测试不足以证明容器完成回调的行为。验证时还应比较并发请求的 trace-id,确认上下文没有串到其他请求。Logbook 自身用于关联请求与响应的 correlation id,也不能直接当作分布式 tracing 的 trace-id。
备注:内容仅供参考。
