前言
程序运行日志对于系统问题排查，业务监控等都是十分重要的，Java记录日志大多通过logback，log4j等框架实现，我之前根据公司的日志规范封装了一个日志插件包，系统需要集成工具包并按照日志打印规范进行日志打印，运维系统使用filebeat收集日志到ES，开发通过ELK（ES，logstah，kibana）查看日志。但是某些很老旧且庞大的系统并没有集成日志工具包，并且因为某些原因一直没有进行改造，这就产生一些问题，比如，数据处理失败在查询日志上非常困难，因为日志中没有处理过程上下文的traceId，这就意味着，打印的各个之日都是断掉的，这根本没办法完成链路追踪。每次排查问题简直不要太痛苦；此外，对于某些接口想从日志中直观的体现出接口执行耗时也是没有的，当然我们可以使用Arthas等工具来做到记录接口耗时，但是每次想查看接口执行耗时都要是用Arthas显然也不合适。痛定思痛，有没有一种办法，在不改造系统对业务代码零入侵的情况下给系统日志中加上traceId和耗时呢？当然有，本篇文章就介绍一下通过javaagent技术+字节码增强logback（我公司用的logback，log4j也可以增强）Logger来实现业务系统代码无入侵增强日志。
增强logback
首先定义traceId的存储，实现在日志内容中增加traceId的能力，我们定义一个类，我这里起名TraceContext就将它定义为链路的上下文，该类中只实现了traceId的能力，如果有特殊需求可以对其进行丰富。下面是TraceContext的代码，使用ThreadLocal存储traceId，提供的两个方法注释中已经说明，至于为什么使用ThreadLocal存储traceId是因为要做到线程隔离，这里具体不解释了。
/***@authorliupenghui*@date2021/10/85:30下午*/publicclassTraceContext{/***存储线程的traceId*/privatestaticfinalThreadLocal<String>TRANSMITTABLE_THREAD_LOCAL=newThreadLocal<>();/***如果ThreadLocal中有traceId就是用否则就生成一个新的*@returntraceId*/publicstaticStringgetTraceId(){StringtraceId=TRANSMITTABLE_THREAD_LOCAL.get();if(StringUtils.isNotBlank(traceId)){returntraceId;}else{//简单使用UUID，可以使用雪花算法，我这里从简，大致演示个意思，并非工业级程序traceId=UUID.randomUUID().toString();TRANSMITTABLE_THREAD_LOCAL.set(traceId);returntraceId;}}/***清理ThreadLocal中的traceId*/publicstaticvoidremove(){TRANSMITTABLE_THREAD_LOCAL.remove();}}然后增强logback的Logger，我这里借鉴了开源工具TLog，使用javassit进行字节码增强，代码如下：
publicclassAspectLogEnhance{publicstaticvoidenhance(){try{CtClasscc=null;try{ClassPoolpool=ClassPool.getDefault();//导入自定义logback增强类LogbackBytesEnhancepool.importPackage("org.agent.enhance.bytes.logback.LogbackBytesEnhance");//增强的类，ch.qos.logback.classic.Loggercc=pool.get("ch.qos.logback.classic.Logger");if(cc!=null){//增强的方法CtMethodctMethod=cc.getDeclaredMethod("buildLoggingEventAndAppend");//增强后的方法体，LogbackBytesEnhance.enhance自己实现的ctMethod.setBody("{returnLogbackBytesEnhance.enhance($1,$2,$3,$4,$5,$6,this);}");cc.toClass();System.out.println("locakback日志增强成功");}}catch(Exceptione){e.printStackTrace();System.out.println("locakback日志增强失败");}}catch(Throwablet){t.printStackTrace();}}}org.agent.enhance.bytes.logback.LogbackBytesEnhance代码如下：
publicclassLogbackBytesEnhance{/***增强ch.qos.logback.classic.Logger的buildLoggingEventAndAppend方法*@paramfqcn*@parammarker*@paramlevel*@parammsg*@paramparams*@paramt*@paramlogger*/publicstaticvoidenhance(finalStringfqcn,finalMarkermarker,finalLevellevel,finalStringmsg,finalObject[]params,finalThrowablet,Loggerlogger){//日志内容StringresultLog;//生成traceIdif(StringUtils.isNotBlank(TraceContext.getTraceId())){//将traceId和日志内容拼接，这里是重点，trceId正是在这里生成并拼接到日志内容中resultLog=StrUtil.format("{}{}",TraceContext.getTraceId(),msg);}else{resultLog=msg;}//增强buildLoggingEventAndAppendLoggingEventloggingEvent=newLoggingEvent(fqcn,logger,level,resultLog,t,params);loggingEvent.setMarker(marker);logger.callAppenders(loggingEvent);}}Web拦截器配置
我这里的程序是基于SpringMVC的，所以我要配置Http请求的拦截器，如果接口是dubbo，SpringCloud等等其他的RPC框架也可以通过其提供的Filter或者拦截器进行处理，我这里就先只实现SpringMVC的拦截器配置，拦截器配置代码如下：
SpringWebInterceptorConfiguration
/***@authorliupenghui*@date2021/10/95:45下午*/@Configuration//有WebMvcConfigurer才加载这个配置@ConditionalOnClass(name={"org.springframework.web.servlet.config.annotation.WebMvcConfigurer"})publicclassSpringWebInterceptorConfiguration{privatestaticfinalLoggerlog=LoggerFactory.getLogger(SpringWebInterceptorConfiguration.class);@BeanpublicWebMvcConfigurationaddWebInterceptor(){log.info("定义Web拦截器");returnnewWebMvcConfiguration();}}WebMvcConfiguration添加拦截器
下面的代码实现了WebMvcConfigurer接口并重写了addInterceptors方法添加拦截器，这里添加了两个拦截器，一个负责清理TraceContext中的traceId，另一个负责记录接口的执行时间。
/***@authorliupenghui*@date2021/10/119:43上午*/publicclassWebMvcConfigurationimplementsWebMvcConfigurer{privatestaticfinalLoggerlog=LoggerFactory.getLogger(WebMvcConfiguration.class);@OverridepublicvoidaddInterceptors(InterceptorRegistryregistry){InterceptorRegistrationinterceptorRegistration;log.info("添加拦截器");//拦截的请求路径interceptorRegistration=registry.addInterceptor(newWebInterceptor()).addPathPatterns("/*");//这里是为了兼容springboot1.5.X，1.5.x没有order这个方法try{Methodmethod=ReflectUtil.getMethod(InterceptorRegistration.class,"order",Integer.class);if(ObjectUtil.isNotNull(method)){method.invoke(interceptorRegistration,Ordered.HIGHEST_PRECEDENCE);}}catch(Exceptione){e.printStackTrace();log.info("traceId拦截器加载失败");}interceptorRegistration=registry.addInterceptor(newTimeInterceptor()).addPathPatterns("/*");//这里是为了兼容springboot1.5.X，1.5.x没有order这个方法try{Methodmethod=ReflectUtil.getMethod(InterceptorRegistration.class,"order",Integer.class);if(ObjectUtil.isNotNull(method)){method.invoke(interceptorRegistration,Ordered.HIGHEST_PRECEDENCE);}}catch(Exceptione){e.printStackTrace();log.info("耗时拦截器加载失败");}}}配置springboot自动装配，在resource/META-INF目录下创建spring.factories内容如下：
org.springframework.boot.autoconfigure.EnableAutoConfiguration=\org.agent.config.SpringWebInterceptorConfiguration
traceId清理拦截器
/***@authorliupenghui*@date2021/10/96:29下午*/publicclassWebInterceptorimplementsHandlerInterceptor{privatestaticfinalLoggerlog=LoggerFactory.getLogger(WebInterceptor.class);@OverridepublicbooleanpreHandle(HttpServletRequestrequest,HttpServletResponseresponse,Objecthandler)throwsException{log.info("拦截到请求");response.addHeader("traceId",TraceContext.getTraceId());returntrue;}@OverridepublicvoidpostHandle(HttpServletRequestrequest,HttpServletResponseresponse,Objecthandler,ModelAndViewmodelAndView)throwsException{HandlerInterceptor.super.postHandle(request,response,handler,modelAndView);}@OverridepublicvoidafterCompletion(HttpServletRequestrequest,HttpServletResponseresponse,Objecthandler,Exceptionex)throwsException{log.info("清理traceId");TraceContext.remove();}}接口耗时拦截器
/***@authorliupenghui*@date2021/10/81:34下午*/publicclassTimeInterceptorimplementsHandlerInterceptor{privatestaticfinalLoggerlog=LoggerFactory.getLogger(TimeInterceptor.class);privatestaticfinalThreadLocal<StopWatch>STOP_WATCH_THREAD_LOCAL=newThreadLocal<>();@OverridepublicbooleanpreHandle(HttpServletRequestrequest,HttpServletResponseresponse,Objecthandler)throwsException{Stringurl=request.getRequestURI();Stringparameters=JSON.toJSONString(request.getParameterMap());log.info("开始请求URL[{}]，参数为：{}",url,parameters);StopWatchstopWatch=newStopWatch();STOP_WATCH_THREAD_LOCAL.set(stopWatch);stopWatch.start();returntrue;}@OverridepublicvoidpostHandle(HttpServletRequestrequest,HttpServletResponseresponse,Objecthandler,ModelAndViewmodelAndView)throwsException{HandlerInterceptor.super.postHandle(request,response,handler,modelAndView);}@OverridepublicvoidafterCompletion(HttpServletRequestrequest,HttpServletResponseresponse,Objecthandler,Exceptionex)throwsException{StopWatchstopWatch=STOP_WATCH_THREAD_LOCAL.get();stopWatch.stop();log.info("结束URL[{}]的调用，耗时为:{}毫秒",request.getRequestURI(),stopWatch.getTime());STOP_WATCH_THREAD_LOCAL.remove();}}编写javaagent程序
logback增强和http接口拦截的能力都已经实现了，现在只需要编写javaagent就行了，代码很简单，在premain方法中AspectLogEnhance.enhance();即可，代码如下：
/***@authorliupenghui*@date2021/10/811:21上午*/publicclassPreAgent{publicstaticvoidpremain(Stringargs,Instrumentationinst){AspectLogEnhance.enhance();}}关于javaagent技术的细节，这里不做介绍，可以参考我转载的文章Javaagent使用指南
制作javaagent包
程序使用maven打包，打包插件如下
<build><finalName>java-agent</finalName><plugins><plugin><artifactId>maven-deploy-plugin</artifactId><configuration><skip>true</skip></configuration></plugin><plugin><groupId>org.apache.maven.plugins</groupId><artifactId>maven-shade-plugin</artifactId><version>1.4</version><executions><execution><phase>package</phase><goals><goal>shade</goal></goals><configuration><keepDependenciesWithProvidedScope>true</keepDependenciesWithProvidedScope><promoteTransitiveDependencies>false</promoteTransitiveDependencies><createDependencyReducedPom>true</createDependencyReducedPom><minimizeJar>false</minimizeJar><createSourcesJar>true</createSourcesJar><transformers><transformerimplementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer"><manifestEntries><Premain-Class>org.agent.PreAgent</Premain-Class></manifestEntries></transformer></transformers></configuration></execution></executions></plugin></plugins></build>
测试
编写测试程序
publicclassAspectLogEnhance{publicstaticvoidenhance(){try{CtClasscc=null;try{ClassPoolpool=ClassPool.getDefault();//导入自定义logback增强类LogbackBytesEnhancepool.importPackage("org.agent.enhance.bytes.logback.LogbackBytesEnhance");//增强的类，ch.qos.logback.classic.Loggercc=pool.get("ch.qos.logback.classic.Logger");if(cc!=null){//增强的方法CtMethodctMethod=cc.getDeclaredMethod("buildLoggingEventAndAppend");//增强后的方法体，LogbackBytesEnhance.enhance自己实现的ctMethod.setBody("{returnLogbackBytesEnhance.enhance($1,$2,$3,$4,$5,$6,this);}");cc.toClass();System.out.println("locakback日志增强成功");}}catch(Exceptione){e.printStackTrace();System.out.println("locakback日志增强失败");}}catch(Throwablet){t.printStackTrace();}}}0测试结果
没有通过javaagent增强的日志效果
没有进行日志增强的测试结果如下图，我调用了4次接口，接口打印的日志没有traceId，可想而知如果业务系统日志查起问题来有多么费劲了。
通过javaagent增强的日志效果
程序启动参数添加javaagent
方法一：
直接IDEA设置程序启动参数，如下图：
方法二：
将测试程序打包，然后执行命令：java -javaagent:你的路径/java-agent.jar -jar 你的路径/java-agent-test.jar
我这里采用方法一了，测试结果如下图：
可以看到红框中日志内容中增加了一个随机串，这就是我们添加的traceId，并且拦截器起到了作用，记录了接口执行耗时，接口执行完成清理掉了当前线程的traceId。
总结
通过javaagent和字节码增强等技术的确实现了代码无入侵的日志增强，但是这么做其实也有一定的局限性，我遇到的问题就是目前还没有办法实现异步日志，比如怎么做到异步日志的链路追踪，因为我之前实现的日志工具包通过com.alibaba.ttl.TransmittableThreadLocal重写MDCAdapter和修饰线程池的方式是可以实现异步日志的，但是我目前这种方式还没有对MDC支持。