【SpringBoot应用篇】SpringBoot+MDC+自定义Filter操作traceId实现日志链路追踪

解决的问题

接口报错，如何快速定位问题？这个需要日志的辅助，一般错误日志中有详细的堆栈信息，具体是哪行代码报错，都可以看到。线程日志交差打印，要想快速定位问题，前提是要能够快速定位日志。

日志量一般都是很大的，如何能够从大量日志中找到自己需要的日志呢？

依赖原始的logback配置，很难从某服务庞杂的日志中，单独找寻出某次线程API调用的全部日志。

解决方案

1、服务端入口处可以生成一个唯一的id，记做：traceId

2、日志中均需要输出traceId的值

3、接口返回值中，添加一个通用的字段：traceId，将上面的traceId作为这个字段的值

• Controller层返回的统一返回值对象R
• 全局异常处理返回的统一返回值对象R

5、这样前端发现接口有问题的时候，直接将这个traceId提供给我们，我们便可以在日志中快速查询出对应的日志。使用 grep 'traceId' xxx.log 语句就能准确的定位到目标日志。

MDC

• 日志追踪目标是每次请求级别的，也就是说同一个接口的每次请求，都应该有不同的traceId。

• 每次接口请求，都是一个单独的线程，所以自然我们很容易考虑到通过ThreadLocal实现上述需求。

• 考虑到logback本身已经提供了类似的功能MDC，所以直接使用MDC进行实现。

• 关于MDC的简述

  • Mapped Diagnostic Context，即：映射诊断环境。
  • MDC是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。
  • MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。

• 关于MDC的关键操作

  • 向MDC中设置值：MDC.put(key, value);
  • 从MDC中取值：MDC.get(key);
  • 将MDC中内容打印到日志中：%X{key}

假定已经解决了traceId的存放问题，那么何时进行traceId的存放呢？其实有多重实现思路，例如：过滤器、AOP、拦截器等等。

具体逻辑

yml

server:port: 8081spring:profiles:active: devapplication:name: springboot-logmain:allow-bean-definition-overriding: true

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration  scan="true" scanPeriod="10 seconds"><!-- 日志级别从低到高分为TRACE < DEBUG < INFO < WARN < ERROR < FATAL，如果设置为WARN，则低于WARN的信息都不会输出 --><!-- scan:当此属性设置为true时，配置文件如果发生改变，将会被重新加载，默认值为true --><!-- scanPeriod:设置监测配置文件是否有修改的时间间隔，如果没有给出时间单位，默认单位是毫秒。当scan为true时，此属性生效。默认的时间间隔为1分钟。 --><!-- debug:当此属性设置为true时，将打印出logback内部日志信息，实时查看logback运行状态。默认值为false。 --><contextName>logback</contextName><!-- name的值是变量的名称，value的值时变量定义的值。通过定义的值会被插入到logger上下文中。定义变量后，可以使“${}”来使用变量。 --><property name="log.path" value="logs/log" /><!-- 彩色日志 --><!-- 配置格式变量：CONSOLE_LOG_PATTERN 彩色日志格式 --><!-- magenta:洋红 --><!-- boldMagenta:粗红--><!-- cyan:青色 --><!-- white:白色 --><!-- magenta:洋红 --><property name="CONSOLE_LOG_PATTERN"value="%X{traceId}|%yellow(%date{yyyy-MM-dd HH:mm:ss}) |%highlight(%-5level) |%blue(%thread) |%blue(%file:%line) |%green(%logger) |%cyan(%msg%n)"/><!--输出到控制台--><appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"><!--此日志appender是为开发使用，只配置最底级别，控制台输出的日志级别是大于或等于此级别的日志信息--><!-- 例如：如果此处配置了INFO级别，则后面其他位置即使配置了DEBUG级别的日志，也不会被输出 --><!--<filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>INFO</level></filter>--><encoder><Pattern>${CONSOLE_LOG_PATTERN}</Pattern><!-- 设置字符集 --><charset>UTF-8</charset></encoder></appender><!--输出到文件--><!-- 时间滚动输出 level为 INFO 日志 --><appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在记录的日志文件的路径及文件名 --><file>${log.path}/log_info.log</file><!--日志文件输出格式--><encoder><pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern><charset>UTF-8</charset></encoder><!-- 日志记录器的滚动策略，按日期，按大小记录 --><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><!-- 每天日志归档路径以及格式 --><fileNamePattern>${log.path}/info/log-info-%d{yyyy-MM-dd}.%i.log</fileNamePattern><timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"><maxFileSize>100MB</maxFileSize></timeBasedFileNamingAndTriggeringPolicy><!--日志文件保留天数--><maxHistory>15</maxHistory></rollingPolicy><!-- 此日志文件只记录info级别的 --><filter class="ch.qos.logback.classic.filter.LevelFilter"><level>INFO</level><onMatch>ACCEPT</onMatch><onMismatch>DENY</onMismatch></filter></appender><!-- 时间滚动输出 level为 WARN 日志 --><appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在记录的日志文件的路径及文件名 --><file>${log.path}/log_warn.log</file><!--日志文件输出格式--><encoder><pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern><charset>UTF-8</charset> <!-- 此处设置字符集 --></encoder><!-- 日志记录器的滚动策略，按日期，按大小记录 --><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><fileNamePattern>${log.path}/warn/log-warn-%d{yyyy-MM-dd}.%i.log</fileNamePattern><timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"><maxFileSize>100MB</maxFileSize></timeBasedFileNamingAndTriggeringPolicy><!--日志文件保留天数--><maxHistory>15</maxHistory></rollingPolicy><!-- 此日志文件只记录warn级别的 --><filter class="ch.qos.logback.classic.filter.LevelFilter"><level>warn</level><onMatch>ACCEPT</onMatch><onMismatch>DENY</onMismatch></filter></appender><!-- 时间滚动输出 level为 ERROR 日志 --><appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在记录的日志文件的路径及文件名 --><file>${log.path}/log_error.log</file><!--日志文件输出格式--><encoder><pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern><charset>UTF-8</charset> <!-- 此处设置字符集 --></encoder><!-- 第一种方式:日志记录器的滚动策略，按日期，按大小记录 --><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><fileNamePattern>${log.path}/error/log-error-%d{yyyy-MM-dd}.%i.log</fileNamePattern><timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"><maxFileSize>100MB</maxFileSize></timeBasedFileNamingAndTriggeringPolicy><!--日志文件保留天数--><maxHistory>15</maxHistory></rollingPolicy><!-- 第二种方式:指定日志文件拆分和压缩规则 --><!-- 指定日志文件拆分和压缩规则 --><!--        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">--><!--            &lt;!&ndash; 通过指定压缩文件名称，来确定分割文件方式&ndash;&gt;--><!--            <fileNamePattern>${log.path}/error/log-error-%d{yyyy-MM-dd}.log%i.zip</fileNamePattern>--><!--            &lt;!&ndash;  文件拆分大小  &ndash;&gt;--><!--            <maxFileSize>1MB</maxFileSize>--><!--            &lt;!&ndash;日志文件保留天数&ndash;&gt;--><!--            <maxHistory>15</maxHistory>--><!--        </rollingPolicy>--><!-- 此日志文件只记录ERROR级别的 --><filter class="ch.qos.logback.classic.filter.LevelFilter"><level>ERROR</level><onMatch>ACCEPT</onMatch><onMismatch>DENY</onMismatch></filter></appender><!--<logger>用来设置某一个包或者具体的某一个类的日志打印级别、以及指定<appender>。<logger>仅有一个name属性，一个可选的level和一个可选的addtivity属性。name:用来指定受此logger约束的某一个包或者具体的某一个类。level:用来设置打印级别，大小写无关：TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF，如果未设置此属性，那么当前logger将会继承上级的级别。--><!--使用mybatis的时候，sql语句是debug下才会打印，而这里我们只配置了info，所以想要查看sql语句的话，有以下两种操作：第一种把<root level="INFO">改成<root level="DEBUG">这样就会打印sql，不过这样日志那边会出现很多其他消息第二种就是单独给mapper下目录配置DEBUG模式，代码如下，这样配置sql语句会打印，其他还是正常DEBUG级别：<logger name="cn.zysheep.mapper" level="INFO" />--><!--结合spring多环境使用 开发环境:打印控制台--><springProfile name="dev"><!--root节点是必选节点，用来指定最基础的日志输出级别，只有一个level属性level:用来设置打印级别，大小写无关：TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF，不写level属性,默认是DEBUG可以包含零个或多个appender元素。--><root level="INFO"><appender-ref ref="CONSOLE" /><appender-ref ref="INFO_FILE" /><appender-ref ref="WARN_FILE" /><appender-ref ref="ERROR_FILE" /></root></springProfile><!--结合spring多环境使用:生产环境:输出到文件--><springProfile name="pro"><root level="INFO"><appender-ref ref="ERROR_FILE" /><appender-ref ref="WARN_FILE" /></root></springProfile>
</configuration>

TraceIdUtil操作工具类

/*** <p>traceId工具类</P>**/
public class TraceIdUtil {public static final String TRACE_ID = "traceId";/*** 当traceId为空时，显示的traceId。随意。*/private static final String DEFAULT_TRACE_ID = "0";/*** 设置traceId*/public static void setTraceId(String traceId) {//如果参数为空，则设置默认traceIdtraceId = StringUtils.isBlank(traceId) ? DEFAULT_TRACE_ID : traceId;//将traceId放到MDC中MDC.put(TRACE_ID, traceId);}/*** 获取traceId*/public static String getTraceId() {//获取String traceId = MDC.get(TRACE_ID);//如果traceId为空，则返回默认值return StringUtils.isBlank(traceId) ? DEFAULT_TRACE_ID : traceId;}/*** 判断traceId为默认值*/public static Boolean defaultTraceId(String traceId) {return DEFAULT_TRACE_ID.equals(traceId);}/*** 生成traceId*/public static String genTraceId() {return UUID.randomUUID().toString();}/*** 判断traceId为默认值*/public static void removeTraceId() {MDC.clear();}
}

TraceIdFilter自定义过滤器

/*** <p>traceId过滤器,用于设置traceId</P>**/
@WebFilter(urlPatterns = "/*", filterName = "traceIdFilter")
@Order(1)
public class TraceIdFilter extends GenericFilterBean {public static Logger logger = LoggerFactory.getLogger(TraceIdFilter.class);@Overridepublic void doFilter(ServletRequest request, ServletResponse response, FilterChain filterChain) throws IOException, ServletException {//traceId初始化initTraceId((HttpServletRequest) request);//执行后续过滤器long st = System.currentTimeMillis();try {filterChain.doFilter(request, response);} finally {long et = System.currentTimeMillis();logger.info("请求地址:{},耗时(ms):{}", ((HttpServletRequest) request).getRequestURI(), (et - st));TraceIdUtil.removeTraceId();}}/*** traceId初始化*/private void initTraceId(HttpServletRequest request) {//尝试获取http请求中的traceIdString traceId = request.getParameter("traceId");//如果当前traceId为空或者为默认traceId，则生成新的traceIdif (StringUtils.isBlank(traceId) || TraceIdUtil.defaultTraceId(traceId)){traceId = TraceIdUtil.genTraceId();}//设置traceIdTraceIdUtil.setTraceId(traceId);}@Overridepublic void destroy() {TraceIdUtil.removeTraceId();}
}

GlobalExceptionHandler全局异常处理类

@Slf4j
@RestControllerAdvice
public class GlobalExceptionHandler {@ExceptionHandler(Exception.class)public R<String> otherExceptionHandler(Exception ex, HttpServletRequest request) {log.warn("Exception:", ex);return R.result(ExceptionCode.SYSTEM_BUSY.getCode(), StringUtils.EMPTY, ExceptionCode.SYSTEM_BUSY.getMsg()).setPath(request.getRequestURI());}
}

TraceIdAspect切面

@Component
@Aspect
@Order
public class TraceIdAspect {/*** 切点:* 1、所有controller包及其子包下的所有方法* 2、所有GlobalExceptionHandler类中的所有方法*/@Pointcut("execution(public * cn.zysheep.controller..*.*(..)) || execution(* cn.zysheep.exception.GlobalExceptionHandler.*(..))")public void pointCut() {}@Around("pointCut()")public Object around(ProceedingJoinPoint pjp) throws Throwable {Object object = pjp.proceed();if (object instanceof R) {((R<?>) object).setTraceId(TraceIdUtil.getTraceId());}return object;}
}

UserController

@RestController
@RequestMapping("/user")
public class UserController {private static final Logger log = LoggerFactory.getLogger(UserController.class);@GetMapping(value = "query")public R findByPage() throws InterruptedException {log.info("开始执行查询用户业务");TimeUnit.MILLISECONDS.sleep(500);log.info("查询用户业务执行结束");return R.success();}@GetMapping("/exception")public R exception()  {log.info("开始执行业务");//这里模拟了一个错误，10/0，会报错System.out.println(10 / 0);log.info("业务执行结束");return R.success();}
}

测试验证

多线程处理

MDCUtil工具类

/*** <p>* 封装MDC用于向线程池传递* </p>*/
public class MDCUtil {// 设置MDC中的traceId值，不存在则新生成，针对不是子线程的情况，// 如果是子线程，MDC中traceId不为nullpublic static void setTraceIdIfAbsent() {if (MDC.get(TraceIdUtil.TRACE_ID) == null) {MDC.put(TraceIdUtil.TRACE_ID, TraceIdUtil.getTraceId());}}public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {return () -> {if (CollectionUtils.isEmpty(context)) {MDC.clear();} else {MDC.setContextMap(context);}setTraceIdIfAbsent();try {return callable.call();} finally {//清除子线程的，避免内存溢出，就和ThreadLocal.remove()一个原因MDC.clear();}};}public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {return () -> {if (context == null) {MDC.clear();} else {MDC.setContextMap(context);}setTraceIdIfAbsent();try {runnable.run();} finally {MDC.clear();}};}public static void setMDCContextMap(final Map<String, String> context) {if (CollectionUtils.isEmpty(context)) {MDC.clear();} else {MDC.setContextMap(context);}}
}

ThreadPoolMdcWrapper

public class ThreadPoolMdcWrapper extends ThreadPoolTaskExecutor {public ThreadPoolMdcWrapper() {}@Overridepublic void execute(Runnable task) {super.execute(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic void execute(Runnable task, long startTimeout) {super.execute(MDCUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout);}@Overridepublic <T> Future<T> submit(Callable<T> task) {return super.submit(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic Future<?> submit(Runnable task) {return super.submit(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic ListenableFuture<?> submitListenable(Runnable task) {return super.submitListenable(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic <T> ListenableFuture<T> submitListenable(Callable<T> task) {return super.submitListenable(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}
}

ContextTransferTaskDecorator

public class ContextTransferTaskDecorator implements TaskDecorator {@Overridepublic Runnable decorate(Runnable runnable) {Map<String, String> context = MDC.getCopyOfContextMap();RequestAttributes requestAttributes = RequestContextHolder.currentRequestAttributes();return () -> {try {MDC.setContextMap(context);RequestContextHolder.setRequestAttributes(requestAttributes);runnable.run();} finally {MDC.clear();RequestContextHolder.resetRequestAttributes();}};}
}

ThreadPoolConfig

@Configuration
public class ThreadPoolConfig {@Bean("poolTaskExecutor")public ThreadPoolTaskExecutor threadPoolTaskExecutor() {ThreadPoolTaskExecutor taskExecutor = new ThreadPoolMdcWrapper();//核心线程数，默认为1taskExecutor.setCorePoolSize(5);//最大线程数，默认为Integer.MAX_VALUEtaskExecutor.setMaxPoolSize(10);//队列最大长度，一般需要设置值>=notifyScheduledMainExecutor.maxNum；默认为Integer.MAX_VALUEtaskExecutor.setQueueCapacity(200);//线程池维护线程所允许的空闲时间，默认为60staskExecutor.setKeepAliveSeconds(60);taskExecutor.setThreadNamePrefix("sif-async-executor-");//线程池对拒绝任务（无线程可用）的处理策略taskExecutor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy());taskExecutor.setTaskDecorator(new ContextTransferTaskDecorator());// 初始化线程池taskExecutor.initialize();return  taskExecutor;}
}

UserController

@RestController
@RequestMapping("/user")
public class UserController {private static final Logger log = LoggerFactory.getLogger(UserController.class);@Resource(name = "poolTaskExecutor")private ThreadPoolTaskExecutor threadPoolExecutor;@GetMapping("/t1")public R test1(){log.info("开始....");CompletableFuture.runAsync(() ->{log.info("异步中....");}, threadPoolExecutor);log.info("结束....");return R.success();}@GetMapping("/t2")public R test2(){log.info("开始....");threadPoolExecutor.execute(() ->{log.info("线程池中....");});log.info("结束....");return R.success();}
}

测试验证