前言: 排查问题是程序员的基本能力也是必须要会的,在开发环境,我们可以debug,但是一旦到了服务器上,就很难debug了,最有效的方式就是通过日志揪出bug,而一次请求的日志如果没有一个唯一的链路标识(我们下边称他为traceId),单靠程序员人工分析的话,费时费力,尤其是请求量高频的接口,更是雪上加霜,排查问题效率大打折扣,作为程序员,低效的方式是忍不了的!!!本文我将用一次实战演练,来演示常用框架中间件多服务之间如何传递traceId 本文大概有如下内容:链路追踪简述和自实现思路单服务内如何实现链路id的输出垮服务调用时,实现链路id传递的各种方式(包含http(openFeign,httpClientrestTemplate)、rpc(motan、dubbo)、mq(RocketMq))异步调用时,如何解决log4j2自带的ThreadLocal丢失链路id问题起4个服务,进行调用,观察链路追踪的效果1、链路追踪实现简述 所谓链路追踪,就是为了把整个请求链路从头到尾串起来,不管调用链路有多深,多复杂,只要将一次链路完整无误的串联起来,就是合格的链路追踪功能。 业界不乏skywalkingzipkin等等链路追踪方面牛逼的框架,但是我们为了更轻量更灵活可控同时也是抱着学习心态,所以自己来实现链路追踪。 首先想实现链路追踪,有两点是核心,实现了这两点,问题也就不大了traceId如何在本地(或者说单服务内)传递?在分布式环境中,traceId如何跨服务中间件传递?2、单体服务的链路追踪 首先我们先讲下单服务内的链路传递 作为java开发,最常用的就是slf4j来实现打印日志的功能(但是slf4j并不没有实现逻辑,因为slf4j整个的定义是一个日志门面,该包中并无具体的实现,实现都是在比如:logbacklog4j2等等日志实现框架中) slf4j的门面不仅给我们提供了打印日志的功能,还提供了org。slf4j。MDC类,该类的作用大概如下: 映射诊断上下文(MappedDiagnosticContext,简称MDC)是一种工具,用于区分不同来源的交错日志输出。当服务器几乎同时处理多个客户机时,日志输出通常是交错的。MDC是基于每个线程进行管理的。 上边这个官方解释,最重要的一句话就是MDC是基于每个线程进行管理的 上边这个太官方,说下我个人对MDC的理解:他是一个日志的扩展,扩展的目的就是给每个线程输出的日志打上一个标记(一个线程只有一个标记且不能重复一般使用uuid即可),这样我们在查看日志时候,就可以根据这个标记来区分调用链路了 ps:当然了,光往MDC中设置当前线程的链路id也是不行的你还得在log4j2。xml文件中,设置占位符,这样最终输出的日志才会带链路信息。如何设置会在2。1节有讲。 从代码层面看下MDC做了啥:MDC类中通过一个MDCAdapter实例调用MDCAdapter的putgetremoveclear等方法。而putgetremoveclear具体的实现是不同厂商来做的比如我常用的log4j2包中就实现了MDCAdapter接口,实现在org。apache。logging。slf4j。Log4jMDCAdapter类中Log4jMDCAdapter类中使用了一个ThreadContext来执行putgetremoveclear逻辑,而ThreadContext中又是一个ThreadContextMapThreadContextMap是一个接口,有不同的实现其中默认的是DefaultThreadContextMap该类中维护了一个ThreadLocalMapString,StringlocalMap类型的成员变量其中map中的k,v就是你调用MDC。put(k,v);时传入的kv最终你调用MDC。put(k,v);时候传入的k和v会被放倒localMap这个ThreadLocal中去。在你给某个线程设置了key,value后,log4j2在打印日志时候,将会去log4j2。xml文件中找占位符等于key的,然后用value把占位符替换,从而打印输出了value(也就是traceId),至此实现了单服务内的链路追踪。 把代码流程梳理下大概如下:MDC(类)MDCAdapter(接口)Log4jMDCAdapter(实现类之一)ThreadContext(类)ThreadContextMap(接口)DefaultThreadContextMap(MDC的几个操作都是往这个里边存取数据)ThreadLocalMapString,StringlocalMap;2。1、如何使用MDC来输出(单服务内的)链路信息?往MDC中设置keyvalue在log4j2。xml中设置占位符(注意:占位符名称要和MDC中的key一致)接着我们简单看下效果:(可以看到,每一个线程,都有一个唯一的链路id) 上边我们说过MDC最终设置的key,value是放到DefaultThreadContextMap类中的ThreadLocalMapString,StringlocalMap这个里边的,也就是说里边的MapString,String是某个线程的本地副本(不懂线程本地副本的可以回顾下ThreadLocal的知识),有了这个知识基础,我们就不难理解为什么输出的日志是每个线程都有唯一的traceId了。 举个例子来说就是:线程t1往MDC中设置的key,value,当log4j2打印t1的日志时,会找到当前(t1)线程设置的value,来把log4j2。xml中的占位符替换线程t2往MDC中设置key,value,当log4j2打印t2的日志时,会找到当前(t2)线程设置的value,来把log4j2。xml中的占位符替换 ok,从上边可以了解到,单服务内通过slf4j提供的MDC功能,可以实现某服务内的链路追踪。 我们都知道,所谓微服务,都是由各个小的单服务组合起来的,通过上边的描述,我们知道单服务内如何打印链路了,那么微服务间不管怎么调用,只要保证在请求最开始(一般是网关)生成一个链路id,在后续的调用中将这个链路id一层层传递下去,整个完整的调用链路追踪也就实现了。在下边小节,我们就看看traceId是怎么垮服务传递的。3、跨服务的链路追踪实现简述 垮服务间调用,本质上就是各个服务之间进行通信的过程,一般情况下,微服务间常用通信方式有如下几种:(这里我们仅从应用层来看,如果从传输层看的话1和2都是tcp)rpchttp消息队列(mq)其他可能我不知道的在日常开发中我常用的: http框架有apache的httpclient,springcloud的openfeign,spring包中的resttemplate,okhttp(okhttp一般安卓用的比较多)。 rpc框架的话一般是dubbo、motan其他的本人没怎么用过。 mq的话我用过kafkarabbitmqrocketmq 下边,我搭建了四个微服务,分别是网关服务studygateway, 微服务消费服务studyconsumer后台管理服务studyadmin订单服务studyorder 在这里我的调用链路大概如下图所示: 如上图所示的链路,该次请求会经过网关,openFeign,异步调用,httpClient调用,mq这几个组件,而如何在这几个组件调用前传递traceId和调用后设置traceId成为垮服务进行链路追踪的关键。ps:dubbo和motan的我们就不演示了,会直接给出传递方案。 铺垫了那么多,我们下边直接了当点不再啰嗦!3。1、在请求最前边(studygateway)添加过滤器 在网关过滤器中生成并设置traceId到MDC(此刻网关服务的日志中将会打印traceId),同时通过header传递到下游服务。 简单看下网关配置: 3。2、在路由目标服务(studyconsumer)中添加过滤器(为了从请求头获取链路id) 3。3、在studyconsumer服务添加feign拦截器(因为consumer要通过feign调用studyadmin服务) 3。4、在studyadmin中添加过滤器(为了从请求头获取链路id) 3。5、在httpClient工具中添加拦截器(对外调用时候往header设置链路id) 3。6、在resttemplate中添加拦截器(对外调用时候往header设置链路id) 注册拦截器到RestTemplate实例: 3。7、在RocketMq发送前和消费前添加钩子 发送前添加钩子: 消费前添加钩子: 分别往生产和消费实例对象中设置钩子: 3。8、用ttl解决异步调用存在的问题(在这里我们也一并说了不再啰嗦) 上边我们也说了,MDC底层DefaultThreadContextMap是用ThreadLocal来保存的链路信息,而ThreadLocal是同一个线程,才会有相同的副本数据,而当我们在项目中使用线程池时候,主线程和子线程肯定是不一样的,那么这种情况下就得考虑如何将主线程的值传递给子线程,让子线程也能记录traceId,从而保证链路不会断! 值的一说的是jdk也想到了这个问题,提供了一个InheritableThreadLocal类,但是这个类并不适用于链路追踪场景,因为在异步调用场景下,是要保证每一次请求,都要将主线程的traceId传递给子线程,而InheritableThreadLocal只能是第一次时候传递,或者说他不是每次都传递给子线程更贴切,下边看下官方的描述: InheritableThreadLocal存在的问题:官方原话:使用InheritableThreadLocal时(ThreadContext可能并不总是自动传递给工作线程) 由于线程池的复用机制,所以第n次请求时,线程池中线程所打印出的链路id,还是上次或者是上n次的链路id(我试验了确实如此),而我们真实希望是,线程池中线程打印的链路id保持和当前主线程中的链路id一致,换句话说:我们需要的是任务提交给线程池时的链路id传递到任务执行时。 既然InheritableThreadLocal不满足需求,那么怎么办呢?看下边: 在log4j2中,他底层是通过spi机制提供了对ThreadContextMap接口的扩展能力,不了解的可以去看看官网,而正好阿里开源了一个这个小框架ttl和ttlthreadcontextmap,ttlthreadcontextmap可以解决线程间的传递丢失问题(他内部也是使用的TransmittableThreadLocal也就是ttl来存储MDC的key和value)。ttlthreadcontextmap依赖java的spi机制,依靠spi机制,让log4j2在启动加载时,用log4j2。component。properties中log4j2。threadContextMap这个key对应的value作为ThreadContextMap接口的实现(也就是替换掉DefaultThreadContextMap这个默认实现),从而实现了线程间传递的功能。对ttl和ttlthreadcontextmap不熟悉的可以跳的github讲的很详细很清楚。 TtlThreadContextMap内部使用TransmittableThreadLocal来存储MDC的key,value spi配置: 而我们使用阿里这个工具也很简单首先maven引入(注意版本不清楚的去maven库看看)dependencygroupIdcom。alibabagroupIdtransmittablethreadlocalartifactIdversion2。14。2versiondependencydependencygroupIdcom。alibabagroupIdlog4j2ttlthreadcontextmapartifactIdexclusionsexclusiongroupIdorg。apache。logging。log4jgroupIdlog4japiartifactIdexclusionexclusionsversion1。4。0versionscoperuntimescopedependency 在引入这个后,我什么也没配,如果我使用jdk的ThreadPoolExecutor或者spring的ThreadPoolTaskExecutor,都是可以实现链路传递的,但是我使用CompletableFuture的话,第一次请求的链路是对的,当第二次请求时候,CompletableFuture线程池中的打印链路信息还是第一次的,这个问题github上有说明,作者让使用javaagent来解决,果然在我配置javaagent后,CompletableFuture的链路信息每次都是正确的。在idea的VMoptions中配置: javaagent:Usershzz。m2repositorycomalibabatransmittablethreadlocal2。14。2transmittablethreadlocal2。14。2。jar 即可解决CompletableFuture的链路id传递问题(这里我们最好是agent这样对代码无侵入,如果你使用TtlRunable修饰Runable的话对代码侵入比较多,维护起来也比较麻烦) 4、跨服务异步链路追踪效果演示 最后我们将四个服务启动,看下整体效果: postman调用: studygateway studyconsumer studyadmin tcpdump抓包看看第三方的请求头中是否含有了链路id: studyorder 上边几张截图可以看到下边这个调用链通过链路id可以完美的串起来了! 至此,垮服务进行链路追踪完成! 最后我将TraceIdUtil代码粘出来。packagecom。xzll。common。util;importcom。xzll。common。constant。StudyConstant;importjodd。util。StringUtil;importorg。apache。commons。lang3。StringUtils;importorg。slf4j。MDC;importjavax。servlet。http。HttpServletRequest;importjava。util。UUID;Author:hzzDate:202322615:19:36Description:publicclassTraceIdUtil{publicstaticfinalStringREGEX;从header和参数中获取traceId从网关传入数据paramrequestHttpServletRequestreturntraceIdpublicstaticStringgetTraceIdByRequest(HttpServletRequestrequest){StringtraceIdrequest。getParameter(StudyConstant。TraceConstant。TRACEID);if(StringUtils。isBlank(traceId)){traceIdrequest。getHeader(StudyConstant。TraceConstant。TRACEID);}returntraceId;}publicstaticStringgetTraceIdByLocal(){returnMDC。get(StudyConstant。TraceConstant。TRACEID);}传递traceId至MDCparamtraceId链路idpublicstaticvoidsetTraceId(StringtraceId){if(StringUtil。isNotBlank(traceId)){MDC。put(StudyConstant。TraceConstant。TRACEID,traceId);}}构建traceIdreturnpublicstaticStringbuildTraceId(){returnUUID。randomUUID()。toString()。replaceAll(REGEX,StringUtils。EMPTY);}清理traceIdpublicstaticvoidcleanTraceId(){MDC。clear();}}5、结尾 由于我的项目中没有使用motan和dubbo所以无法演示rpc调用,但是我接触的项目有,这里不粘完整代码了,直接给出答案,在motan中也是支持配置过滤器的,在调用前,通过过滤器往request的attachment中设置traceId来将traceId传递给服务提供者,在服务提供者中也可以添加过滤器,此时从attachment属性中取出traceId通过MDC。put(key,value)来将traceId设置进本服务。达到链路传递的效果。同理dubbo框架也是类似做法。 ps:由于时间原因,我的四个服务中,有多处冗余代码,比如过滤器,这些类似公共的都可以抽出来搞一个starter或者是导入bean等等方式,来减少重复代码。由于本文重点讲述使用方面的东西,原理方面的不做过多解散,关于ttl和log4j2ttlthreadcontextmap,可以看看github的资料,已经讲的超级细了。另外如果像知道更多细节,需要从slf4j和log4j2的源码入手,相信会有更多的收获。你会发现每天使用的slf4jlog4j2里边居然这么多值的学习的地方!!!