在单体SpringBoot项目中，虽然没有复杂的微服务调用，但是查看日志依然是一件很头痛的事情，当我需要要梳理出某一个接口调用过程中产生的所有日志，往往需要根据线程ID和时间戳来筛选出我们需要的日志数据。
针对这个问题，我产生了一个念头，为每次接口调用生成一个TraceId用于追踪本次调用过程中产生的日志。
基本思路是，借助于Spring的HandlerInterceptor接口，实现对每次调用的前后处理，在调用前生成一个TraceId存放到ThreadLocal中，在调用完成后，清理该ThreadLocal。
在最初的实现版本中，在日志中记录TraceId的工作需要手动完成。
后来想到了Logback的Converter,于是就优化了实现，将其统一加入到日志中，不再污染日志代码。
TraceId的生成相对比较简单，直接使用了UUID。
在代码实现上，TraceContextHolder用于维护每个线程的TraceId
import org.springframework.util.StringUtils;
import java.util.UUID;
/**
* 用于链路追踪
* @author HanQi [Jpanda@aliyun.com]
* @version 1.0
* @since 2019/12/6 10:40
*/
public class TraceContextHolder {
private static final ThreadLocal<String> TRACE_INFO= ThreadLocal.withInitial(() -> UUID.randomUUID().toString().replaceAll("-",""));
public static void init(){
if (StringUtils.isEmpty(TRACE_INFO.get())){
TRACE_INFO.set(UUID.randomUUID().toString().replaceAll("-",""));
}
}
public static String getTrace(){
return TRACE_INFO.get();
}
public static void clear(){
TRACE_INFO.remove();
}
}
TraceHandlerInterceptor负责为每次请求生成TraceId和在请求玩抽清理TraceId。
/**
* 便于日志追踪
* @author HanQi [Jpanda@aliyun.com]
* @version 1.0
* @since 2019/12/6 10:37
*/
public class TraceHandlerInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
TraceContextHolder.init();
return true;
}
@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
TraceContextHolder.clear();
}
}
WebMvcConfiguration实现了WebMvcConfigurer接口，负责完成拦截器的注册工作。
@Configuration
public class WebMvcConfiguration implements WebMvcConfigurer {
@Override
public void addInterceptors(InterceptorRegistry registry) {
// 链路追踪
registry.addInterceptor(new TraceHandlerInterceptor());
}
}
上面的代码，已经足够支撑我们使用简单的链路追踪能力了。
log.info("TraceId:{},实际日志信息", TraceContextHolder.getTrace());
但是这种方式还是不够友好，需要污染我们的日志记录代码，不仅增加了代码量，连后期的维护也变得复杂，比如,当我们需要移除或者替换链路追踪功能时，需要调整大量的代码，或者冗余无效代码。
因此在这个基础上，借助于logback的Converter转换器功能，通过自定义占位符的解析来进一步完成链路追踪的能力。
TraceMessageConverter实现了ClassicConverter接口，作用是在当前日志中追加TraceId的输出能力。
import ch.qos.logback.classic.pattern.ClassicConverter;
import ch.qos.logback.classic.spi.ILoggingEvent;
import com.xiling.configuration.trace.TraceContextHolder;
/**
* %trace 占位符的解析器，作用是获取当前TraceId
*
* @author HanQi [Jpanda@aliyun.com]
* @version 1.0
* @since 2019/12/7 11:32
*/
public class TraceMessageConverter extends ClassicConverter {
@Override
public String convert(ILoggingEvent event) {
return TraceContextHolder.getTrace();
}
}
修改logback的配置文件，注册TraceMessageConverter到logback中，并告诉logback``TraceMessageConverter用于解析pattern表达式中%trace占位符。
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<conversionRule conversionWord="trace" converterClass="完整包名.TraceMessageConverter"/>
</configuration>
接下来我们只需要在我们的pattern表达式中添加%trace参数即可。
<!-- ch.qos.logback.core.ConsoleAppender 控制台输出 -->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>[%-5level] %d{HH:mm:ss.SSS} [%thread] [%X{X-B3-TraceId}] [%trace] %logger{36} - %msg%n
</pattern>
</encoder>
</appender>
一个完整的logback配置
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<property name="APP_NAME" value="APP_NAME"/>
<property name="LOG_HOME" value="/data/logs/${APP_NAME}"/>
<property name="ENCODER_PATTERN"
value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%10.10thread] [%X{X-B3-TraceId}] %logger{20} - %msg%n"/>
<contextName>${APP_NAME}</contextName>
<conversionRule conversionWord="trace" converterClass="完整包名.TraceMessageConverter"/>
<appender name="FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_HOME}/${APP_NAME}.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${LOG_HOME}/backup/${APP_NAME}.%d{yyyy-MM-dd}.log
</fileNamePattern>
<maxHistory>100</maxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>${ENCODER_PATTERN}</pattern>
</encoder>
</appender>
<appender name="ERROR_FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_HOME}/error.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${LOG_HOME}/backup/error.%d{yyyy-MM-dd}.log
</fileNamePattern>
<maxHistory>100</maxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>${ENCODER_PATTERN}</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>ERROR</level>
</filter>
</appender>
<!-- ch.qos.logback.core.ConsoleAppender 控制台输出 -->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>[%-5level] %d{HH:mm:ss.SSS} [%thread] [%X{X-B3-TraceId}] [%trace] %logger{36} - %msg%n
</pattern>
</encoder>
</appender>
<root>
<level value="info"/>
<appender-ref ref="console"/>
<appender-ref ref="FILE"/>
<appender-ref ref="ERROR_FILE"/>
</root>
</configuration>
接下来，当我们在代码中正常使用logback功能即可在日志中获取traceId。
log.info("简单的输出");
实际日志为:
[INFO ] 17:43:50.097 [http-nio-8080-exec-7] [] [cd21d506088649809000a3de4c66650e] c.j.t.TraceShower - 简单的输出
日志中的cd21d506088649809000a3de4c66650e就是我们生成的TraceId。
这样，当我们需要定位具体的接口调用日志时，只需要使用类似于awk '{print}' log.file|grep TraceId的方式即可。
这只是一个简单的链路追踪的代码，有很多缺陷，比如，不支持调用中的多线程，虽如此，但也简单满足了基本的使用。
如果需要解决多线程的链路追踪问题，可以参考TransmittableThreadLocal。
网友评论