接手一个内部订单系统的那段时间我最大的感受就是日志永远在最需要的时候变得不可用。生产环境偶发超时一台实例的日志里同时混着十几个并发请求同一个用户ID的操作散落在不同线程、不同时间戳我要一个点一个点地拼凑才知道这个请求到底走到哪一步断掉了。后来我收拾完这套烂摊子给整个SpringBoot服务统一接入了TraceId日志链路追踪从那次之后排障变成了按ID查日志和之前完全是两种体验。这篇文章不讲云里雾里的概念我从一个Java后端开发的角度把TraceId的生成、存储、HTTP传递、跨线程传递、日志配置这些关键环节完整拆开给出可以直接拿去用的实现思路。适合那种服务数量不算多、还没上重型APM系统、但已经在为日志排查头疼的中小型团队。如果你已经在用完整链路追踪系统下面的方法同样可以作为你基础日志层的补充。1. 日志碎片化带来的排障难题TraceId到底在解决什么1.1 一次典型请求在日志里的五段散装记录先看一组没有TraceId时最常见的日志输出2024-06-11 10:00:01.152 [http-nio-8080-exec-6] INFO OrderController - 收到创建订单请求 userId10086 2024-06-11 10:00:01.286 [pool-3-thread-1] INFO StockService - 扣减库存 goodsId5015 result1 2024-06-11 10:00:01.290 [http-nio-8080-exec-6] INFO OrderService - 订单保存成功 orderId202406110001第一眼看上去这三条日志的时间很接近但它们之间是什么关系http-nio-8080-exec-6和pool-3-thread-1已经换了一个线程而线程ID这东西是会复用、会跳动的。如果不把orderId、userId这些业务ID打进去你会非常难确认StockService那条日志到底属于哪一次创建订单。更麻烦的是很多日志点压根没有业务ID比如缓存写入失败远程配置刷新完成。一旦请求跨了多个机器比如网关转发到A服务A服务通过HTTP调用B服务B服务再回调C服务日志就散落在三台服务器的不同文件里。这时候靠时间排序去拼接一次调用链基本等于凭记忆做拼图。1.2 为什么线程ID和时间戳都兜不住这个场景线程ID能标识的是操作系统里的一个执行线程而不是一次业务请求。一次请求在SpringBoot里可能经历Tomcat工作线程、线程池里的异步线程、MQ消费线程、定时任务线程。线程一变关联马上就断了。而且线程ID是复用的一个处理完请求的池线程下一次可能处理另一个完全无关的请求日志里就会出现线程号相同但请求完全不同的情况。时间戳也有同样的问题。同一条服务的高峰期一秒内可能有几十个请求都落在同一毫秒级日志之间靠时间做关联根本不现实。多实例部署之后不同机器的时钟还可能存在微小偏移时间排序就更容易出错。1.3 边界要提前讲清楚TraceId不等于全链路监控我看到过一些团队误以为有了TraceId就有了全链路监控。这是两码事。TraceId解决的问题非常聚焦给一次请求分配一个唯一标识并让这个标识贯穿所有日志输出让你能回答这个请求都经过了哪些地方、在每个地方发生了什么。它不回答A服务调用B服务到底花了多少毫秒哪个调用环节最慢这类性能拓扑问题。所以做技术选型时我建议这样分关注点轻量方案重型方案日志关联、排障定位TraceId 日志聚合平台链路追踪系统服务调用耗时统计手动埋点或中间件指标链路追踪系统依赖拓扑自动发现基本做不到链路追踪系统中小团队如果只是想快速解决日志找不到关联的痛点先做TraceId是完全够用的。后面如果真需要拓扑分析再上重型链路追踪系统也不迟TraceId反而能作为对接时的一个基础字段不会白做。2. 落地核心三角Filter生成、MDC存储、日志Pattern输出2.1 选什么当TraceIdUUID基础上的改造思路TraceId本身就是一个字符串关键要求是全局唯一、尽量短、不能有特殊字符。最简单的做法是直接用UUIDpublic static String generateTraceId() { return UUID.randomUUID().toString().replace(-, ).substring(0, 24); }UUID.randomUUID()去掉连字符后是32位截成24位在大多数业务场景下冲突概率已经足够低。不要一来就设计复杂的雪花ID方案除非你们有明确要求比如希望从TraceId里能看出生成时间、所在节点。真要可读性可以像我一样做一个简单组合public static String generateTraceId() { return Long.toHexString(System.currentTimeMillis()) Integer.toHexString(ThreadLocalRandom.current().nextInt(Integer.MAX_VALUE)) nodeIdSuffix; }其中nodeIdSuffix是启动时从环境变量读出来的节点编号。这样生成的ID一眼能看出大约什么时间产生的日志里信息量更足。但有一点要记住TraceId的作用是关联不是审计不要为了可读性牺牲太长控制在32位以内比较舒服否则一行日志会被撑得很宽。2.2 OncePerRequestFilter里写MDC的正确姿势MDC是SLF4J提供的诊断上下文底层本质是ThreadLocal。也就是说你在当前线程往MDC里放了一个值当前线程后续打印的所有日志都能通过%X{traceId}把它取出来。这正是我们想要的效果不用改任何业务日志代码。核心代码放在一个Filter里Component public class TraceIdFilter extends OncePerRequestFilter { private static final String TRACE_ID_HEADER X-Trace-Id; private static final String TRACE_ID traceId; Override protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException { String traceId request.getHeader(TRACE_ID_HEADER); if (!StringUtils.hasText(traceId)) { traceId generateTraceId(); } MDC.put(TRACE_ID, traceId); response.setHeader(TRACE_ID_HEADER, traceId); try { filterChain.doFilter(request, response); } finally { MDC.remove(TRACE_ID); } } }这里有两个细节非常关键。第一个用OncePerRequestFilter而不是普通Filter。Spring的过滤器在被转发、异常分发等场景下同一个请求可能会经过多次普通Filter不能保证只执行一次。而OncePerRequestFilter从命名上就保证了每个请求只执行一次避免重复生成TraceId或重复设置响应头。第二个MDC.remove必须放在finally里。Tomcat的工作线程是池化复用的如果不清理这个线程处理完当前请求后traceId还留在ThreadLocal里下一个被该线程处理的无相关请求的日志就会带着上一个请求的TraceId出现。这个问题非常隐蔽排障时你会看到两条不同用户的请求共用一个TraceId日志互相串线。2.3 Logback的Pattern里打开%X开关MDC里放了值日志框架还要知道从哪取。以Logback为例在logback-spring.xml里把pattern加上%X{traceId}appender nameSTDOUT classch.qos.logback.core.ConsoleAppender encoder pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - [%X{traceId:-}] - %msg%n/pattern /encoder /appender注意%X{traceId:-}后面的:-意思是如果当前线程的MDC里没有traceId则输出空字符串。如果你的项目用Log4j2写法是%X{traceId}效果相同。这一步做完所有经过TraceIdFilter的请求日志里都会带上一个方括号包裹的TraceId字段。这时候你再回头看上面那组散装日志会变成2024-06-11 10:00:01.152 [http-nio-8080-exec-6] INFO OrderController - [a1b2c3d4e5f6a7b8c9d0e1f2] - 收到创建订单请求 userId10086 2024-06-11 10:00:01.286 [pool-3-thread-1] INFO StockService - [a1b2c3d4e5f6a7b8c9d0e1f2] - 扣减库存 goodsId5015 result1 2024-06-11 10:00:01.290 [http-nio-8080-exec-6] INFO OrderService - [a1b2c3d4e5f6a7b8c9d0e1f2] - 订单保存成功 orderId202406110001线程还是变来变去但方括号里的TraceId一样我们马上就能判断这三条日志属于同一个请求。2.4 在响应头回传TraceId给前端和排查同事一个定位锚点除了日志里能看到TraceId我强烈建议你在HTTP响应头里返回它。上面Filter里的response.setHeader(TRACE_ID_HEADER, traceId)就是干这个的。这样前端同学在浏览器开发者工具里或者调用方服务在响应的Header里都能直接看到X-Trace-Id字段。这带来的改观是用户报障说我刚刚下单失败了你只要问他把失败请求的TraceId发我然后拿着这个ID去日志系统一搜几秒钟就能看到这个请求在所有服务里的完整路径。不用再反复问用户ID、订单ID、操作时间。这个习惯一旦养成整个团队的排障效率会明显上一个台阶。放Header的一个小坑是如果你是在Filter最后才setHeader而业务在Filter执行过程中已经把响应提交了比如已经往OutputStream里写了数据那这个Header就写不上去了。所以我把setHeader放在Filter开头而不是finally里这样只要响应还没被提交Header就能带上。3. 跨服务与跨网关传递TraceId的请求头接力赛3.1 Feign的RequestInterceptor透传单服务内部的TraceId已经通了但线上真实系统很少只有一个服务。A服务调用B服务时B服务根本不知道上游的TraceId如果B服务在它的Filter里又生成了一个新TraceId链路就断了。所以要解决的是透传。以SpringCloud的Feign为例定义一个全局的RequestInterceptorBean public RequestInterceptor traceIdPropagationInterceptor() { return requestTemplate - { String traceId MDC.get(traceId); if (traceId ! null) { requestTemplate.header(X-Trace-Id, traceId); } }; }这个拦截器会在Feign构造请求头时执行把当前线程MDC里的traceId塞进请求头。前提是Feign调用仍然发生在原请求线程内。如果你开启了Feign的异步调用、或者配了独立的线程池那MDC里的traceId可能已经丢了这时需要先解决跨线程传递的问题见第4章。3.2 RestTemplate/Apache HttpClient的加头统一封装不使用Feign的项目一般会直接用RestTemplate。同样可以用ClientHttpRequestInterceptor统一处理Bean public RestTemplate traceAwareRestTemplate() { RestTemplate restTemplate new RestTemplate(); restTemplate.getInterceptors().add((request, body, execution) - { String traceId MDC.get(traceId); if (traceId ! null) { request.getHeaders().set(X-Trace-Id, traceId); } return execution.execute(request, body); }); return restTemplate; }这样在所有通过这个RestTemplate发起的HTTP调用里都会自动带上当前请求的TraceId。不建议每个调用的地方手动设置Header因为人总会忘记而且一旦服务多了漏一个就断一截。如果你项目里用的是Apache HttpClient思路也完全一样写一个HttpRequestInterceptor在preRequest阶段从MDC取值并设置Header。原理都是在出站请求的构造点统一注入。3.3 接收方取出请求头时的一个小心机上游给的别覆盖上面说Filter里我们用的是String traceId request.getHeader(TRACE_ID_HEADER); if (!StringUtils.hasText(traceId)) { traceId generateTraceId(); }这个逻辑非常重要上游如果已经传了TraceId下游必须优先使用而不是重新生成。一旦你优先重新生成整个链路在每一跳都是新ID跨服务排查直接失去意义。只有请求头里没有TraceId的请求才需要自己生成一个比如外部客户端、定时任务、MQ消费者触发的入口请求。另外对入站请求头里的TraceId要做合法性校验。遇到过有人故意传一个几千字节的超长非法值进日志系统造成日志注入。我的做法是private static final Pattern TRACE_ID_PATTERN Pattern.compile(^[a-zA-Z0-9-]{1,64}$); public static boolean isValidTraceId(String traceId) { return traceId ! null TRACE_ID_PATTERN.matcher(traceId).matches(); }不合法就不采用直接生成新的既安全又省心。Nginx层如果做了proxy_set_header X-Trace-Id $http_x_trace_id;那上游入站请求的X-Trace-Id就能原样传给下游服务如果没配默认也会转发客户端请求头大部分场景下不需要额外处理。4. 异步线程池、MQ消费者、定时任务MDC不继承的连锁反应4.1 子线程为什么是空白ThreadLocal隔离的根因Filter往MDC里放值相当于在当前线程的一个ThreadLocal变量里写了数据。Java里ThreadLocal的含义就是线程局部变量子线程默认是读不到父线程的ThreadLocal的。这导致一个非常典型的翻车场景// Controller中用线程池异步执行任务 executor.submit(() - { log.info(异步任务开始当前traceId{}, MDC.get(traceId)); });上面这行日志的MDC.get(traceId)大概率是null。异步线程是一个全新的线程它没有父线程的MDC副本。如果你不看线程名你会以为TraceId丢了其实是不继承。还有一个隐藏问题线程池里的线程会被多个任务复用。如果不处理前一个任务在子线程里写入的traceId会残留后一个任务进来如果没写新的traceId日志就会错误地带着上一个任务的TraceId造成严重的串线。4.2 用TaskDecorator给线程池自动传递TraceIdSpringBoot里有一个很优雅的扩展点ThreadPoolTaskExecutor.setTaskDecorator。它可以在任务提交时拿一次上下文在执行时再放进去。实现如下Bean(traceAwareExecutor) public ThreadPoolTaskExecutor traceAwareExecutor() { ThreadPoolTaskExecutor executor new ThreadPoolTaskExecutor(); executor.setCorePoolSize(2); executor.setMaxPoolSize(8); executor.setQueueCapacity(100); executor.setThreadNamePrefix(trace-pool-); executor.setTaskDecorator(runnable - { MapString, String contextMap MDC.getCopyOfContextMap(); return () - { if (contextMap ! null) { MDC.setContextMap(contextMap); } try { runnable.run(); } finally { MDC.clear(); } }; }); executor.initialize(); return executor; }关键是在执行runnable.run()之前把父线程的MDC上下文Map复制到当前子线程执行完再MDC.clear()。为什么一定要清理因为线程池的线程本身是复用的如果不清理这个子线程下一次执行别的任务时会带着上一个任务的traceId过日子。如果你用了Async注解同样可以配置AsyncConfigurerConfiguration public class AsyncConfig implements AsyncConfigurer { Override public Executor getAsyncExecutor() { return traceAwareExecutor(); } }这样被Async修饰的方法在异步执行时也能自动带上父线程的TraceId。4.3 批量异步场景的合并与还原还有一种场景一个请求里循环提交多个异步任务每个任务都想带同一个TraceId。有同学会写成for (SomeTask task : tasks) { executor.submit(() - { // 打印日志 }); }看起来没毛病但由于TaskDecorator已经统一处理了MDC复制你只需要保证提交时父线程的MDC里有正确的traceId就行。不需要在循环里反复MDC.put那反而会干扰。要注意的是如果子线程内部自己又调用了其它工具类并往MDC里放了别的字段MDC.clear()会把它们一起清掉。如果你只想清理traceId可以改成MDC.remove(traceId)。但从防止串线的角度clear()更干净。业务代码里不建议乱放自定义MDC字段除非有统一的规范。4.4 定时任务和MQ消费入口要显式生成TraceId定时任务和MQ消费者没有经过Spring的HTTP请求过滤器所以它们启动时的MDC是空的。如果你想让定时任务日志也有链路可查就要在入口自己生成TraceId。最简单的方式try { MDC.put(traceId, generateTraceId()); ScheduledTaskExecutor.run(); } finally { MDC.remove(traceId); }MQ消费端同样如果MQ消息头里带了上游的TraceId就优先取消息头里的没有就自己生成一个。很多团队在发MQ消息时也会把TraceId写进消息头这样消费者拿到后整条消息链依然可以关联起来。这一步虽然只是几行代码但往往能让你在排查一个消息为什么没处理成功的问题时直接找到生产这条消息的原始请求。5. 生产环境常见的翻车点提升日志质量的最后几件事5.1 日志里一会儿有TraceId一会儿没有先查这四处我见过很多团队配完TraceId之后日志里仍然断断续续。如果你也遇到这种情况建议按这个顺序排查现象可能原因检查方向所有日志都没有TraceIdFilter没生效或Pattern没配置确认Filter被Spring扫描、确认logback xml加载同一个请求出现多个不同TraceId上游传了但下游重新生成检查接收方是否优先读请求头只有Controller层有TraceId异步线程没有继承检查线程池有没有接入TaskDecorator不同请求的TraceId串线线程池执行后没有清理MDC检查finally里是否做remove或clear5.2 日志量大时TraceId检索效率也会变差TraceId只是帮找到日志但日志本身太多检索也不会快。几个建议一是不要在for循环里打印日志二是服务入口打印一次请求开始出口打印一次请求结束中间过程用debug级别三是如果日志平台支持字段检索最好把TraceId单独映射成结构化字段而不是只存在一长串message文本里。最简单的做法是使用JSON格式的日志输出让MDC字段变成独立的JSON字段这样日志平台里就能按traceId做精确的条件过滤比模糊搜文本快得多。5.3 全局异常处理器里记得把TraceId带上排障时最需要TraceId的地方除了正常的请求日志还有异常告警。很多时候系统出错你看到一条ERROR日志但没有上下文根本不知道是哪个请求触发的。所以我会在全局异常处理器里把当前MDC里的TraceId取出来一起输出ExceptionHandler(Exception.class) public ResponseEntityErrorResult handleException(Exception e) { String traceId MDC.get(traceId); log.error(unexpected error, traceId{}, traceId, e); // 返回体里也可以带上traceId }这样一条异常信息里同时有异常堆栈和关联请求ID后续不管谁接手第一时间知道问题是哪个请求引发的。5.4 我踩过几次坑之后的小习惯最后说一个我自己的实操习惯。TraceId接入稳定之后我把所有服务对外调用的响应头都统一成X-Trace-Id并且在错误返回结构里也放一个traceId字段。这样前端、调用方、后端排查人员三方对齐的永远是同一个ID字段避免各喊各的。后来有一次用户报障我把响应里的TraceId拷到日志平台几秒就定位到了具体是数据库慢查询导致的超时从接到反馈到确认根因不超过5分钟这在没有TraceId的年代是不可想象的。排障快和慢的区别往往就落在这一串看似不起眼的ID上。