SpringBoot+MDC链路追踪trace_id丢失

前言

trace_id是用来标识同一个请求的唯一标识，不管请求经过多少服务，都可以通过tracid排查对应模块的日志信息找到对应请求的一些细节，是排查问题的一个重要线索。

在当下分布式系统相对成熟的环境下，链路追踪方案百花齐放，各种中间件层出不穷，不知道选哪个好。不过在早期的分布式应用里的链路追踪是自己实现的，以至于模块之间的调用有时会出现tracid为空的情况。这次正好遇到了这个bug，正好记录下。

首先先介绍下内部早期服务的链路追踪方案，Java服务这块是使用的SpringBoot+MDC实现，按正常的思路参数里默认加上了trace_id参数，进到服务的第一层时先判断当前线程上下文中是否存在trace_id变量，没有的话从请求参数里获取trace_id变量，如果请求中也没有则认为是入口请求，随机生成一个uuid作为trace_id向下传递。

MDC

MDC是一个映射，用于存储运行上下文的特定线程的上下文数据，本质上是一层对ThreadLocal的封装，在logback-spring.xml中配置上打印规则，使用log4j进行日志打印出每个应用的trace_id

css复制代码[%X{TRACE_ID}]

方案合情合理，页面端发起请求，网关服务生成trace_id向下传递，每个服务依次传递都很和谐，但就是在某个地方出现A服务通过RPC组件调用B服务时出现了BUG。这种年久失修的问题谁都不想改，但没办法指到了我这了只能硬着头皮查了。

理论上MDC绑定了线程信息，而且trace_id丢失的场景下没有多线程线程切换的场景，那么只能把矛头指向祖传的拦截器和过滤器了。

拦截器与过滤器

由于一些历史原因，一个Java服务夹杂着各种过滤器、过滤器，有的是自身服务的，有的是二方包里的，搞得一个请求链路错综复杂。顺着日志一条一条看，发现在进入到接口层之前trace_id一直是对的，在执行完接口后就出现了问题，trace_id值变了，也就是一个请求出现了两个trace_id。

仔细分析一下其实不难定位，问题的根源其实来自于拦截器与过滤器的机制，这里先回顾一个老八股，在springboot应用中一个请求是执行到拦截器还是先执行到过滤器？ 答案是毋庸置疑的，肯定先执行到过滤器Filter再执行到拦截器Interceptor。

那么错综复杂的各种拦截机制在老版本的服务里构造成了一个类似洋葱模型的拦截机制，请求在进入服务之前先进行一些业务日志处理和请求参数的校验，在请求走完逻辑之后，又会重新再走每个拦截器过滤器的post方法。

如果请求进入到接口层之前没问题，在执行完接口后就出现了问题，那么肯定是某个组件搞了幺蛾子把MDC里的东西搞丢了。

lua复制代码+-----  common_filter  -----+
| +---- a_interceptor ----+ |
| | +-- b_interceptor --+ | |
| | |                   | | |
| | |    interface      | | |
| | |                   | | |
| | +-- b_interceptor --+ | |
| +---- a_interceptor ----+ |
+-----  parentA_filter -----+

理一下逻辑，当请求某个服务的接口时，请求会先进入统一的公共过滤器common_filter，在这一层会打印出访问的uri、以及来源ip等等信息，并生成trace_id放入MDC中向下传递。当进入到a_interceptor、b_interceptor都没问题，统一先从MDC中取出来，如果没有取到判断参数中有没有trace_id，没有的话就重新生成一个（其实这个逻辑也应该优化下，现在成熟的链路追踪方案都是放到header中，这里应该判断header和参数）。

仔细排查当请求被服务处理完之后会发现后续的trace_id都不对了，在b_interceptor就断掉了，去对应的二方库里扒拉出来一看。

前言

trace_id是用来标识同一个请求的唯一标识，不管请求经过多少服务，都可以通过tracid排查对应模块的日志信息找到对应请求的一些细节，是排查问题的一个重要线索。

在当下分布式系统相对成熟的环境下，链路追踪方案百花齐放，各种中间件层出不穷，不知道选哪个好。不过在早期的分布式应用里的链路追踪是自己实现的，以至于模块之间的调用有时会出现tracid为空的情况。这次正好遇到了这个bug，正好记录下。

首先先介绍下内部早期服务的链路追踪方案，Java服务这块是使用的SpringBoot+MDC实现，按正常的思路参数里默认加上了trace_id参数，进到服务的第一层时先判断当前线程上下文中是否存在trace_id变量，没有的话从请求参数里获取trace_id变量，如果请求中也没有则认为是入口请求，随机生成一个uuid作为trace_id向下传递。

MDC

MDC是一个映射，用于存储运行上下文的特定线程的上下文数据，本质上是一层对ThreadLocal的封装，在logback-spring.xml中配置上打印规则，使用log4j进行日志打印出每个应用的trace_id

css复制代码[%X{TRACE_ID}]

方案合情合理，页面端发起请求，网关服务生成trace_id向下传递，每个服务依次传递都很和谐，但就是在某个地方出现A服务通过RPC组件调用B服务时出现了BUG。这种年久失修的问题谁都不想改，但没办法指到了我这了只能硬着头皮查了。

理论上MDC绑定了线程信息，而且trace_id丢失的场景下没有多线程线程切换的场景，那么只能把矛头指向祖传的拦截器和过滤器了。

拦截器与过滤器

由于一些历史原因，一个Java服务夹杂着各种过滤器、过滤器，有的是自身服务的，有的是二方包里的，搞得一个请求链路错综复杂。顺着日志一条一条看，发现在进入到接口层之前trace_id一直是对的，在执行完接口后就出现了问题，trace_id值变了，也就是一个请求出现了两个trace_id。

仔细分析一下其实不难定位，问题的根源其实来自于拦截器与过滤器的机制，这里先回顾一个老八股，在springboot应用中一个请求是执行到拦截器还是先执行到过滤器？ 答案是毋庸置疑的，肯定先执行到过滤器Filter再执行到拦截器Interceptor。

那么错综复杂的各种拦截机制在老版本的服务里构造成了一个类似洋葱模型的拦截机制，请求在进入服务之前先进行一些业务日志处理和请求参数的校验，在请求走完逻辑之后，又会重新再走每个拦截器过滤器的post方法。

如果请求进入到接口层之前没问题，在执行完接口后就出现了问题，那么肯定是某个组件搞了幺蛾子把MDC里的东西搞丢了。

lua复制代码+-----  common_filter  -----+
| +---- a_interceptor ----+ |
| | +-- b_interceptor --+ | |
| | |                   | | |
| | |    interface      | | |
| | |                   | | |
| | +-- b_interceptor --+ | |
| +---- a_interceptor ----+ |
+-----  parentA_filter -----+

理一下逻辑，当请求某个服务的接口时，请求会先进入统一的公共过滤器common_filter，在这一层会打印出访问的uri、以及来源ip等等信息，并生成trace_id放入MDC中向下传递。当进入到a_interceptor、b_interceptor都没问题，统一先从MDC中取出来，如果没有取到判断参数中有没有trace_id，没有的话就重新生成一个（其实这个逻辑也应该优化下，现在成熟的链路追踪方案都是放到header中，这里应该判断header和参数）。

仔细排查当请求被服务处理完之后会发现后续的trace_id都不对了，在b_interceptor就断掉了，去对应的二方库里扒拉出来一看。

那么好了好了，一切都说通了，不知道哪路神仙在b_interceptor的post方法里把MDC给清除了，导致后续处理trace_id都不对。开始没啥思路我都怀疑是不是tomcat切换线程的bug了，甚至出现了要给springboot换undertow容器的念头。

还好打消了，不然摸鱼的时间又少了

那么好了好了，一切都说通了，不知道哪路神仙在b_interceptor的post方法里把MDC给清除了，导致后续处理trace_id都不对。开始没啥思路我都怀疑是不是tomcat切换线程的bug了，甚至出现了要给springboot换undertow容器的念头。

还好打消了，不然摸鱼的时间又少了