【SpringBoot应用篇】SpringBoot+MDC+自定义Filter操作traceId实现日志链路追踪
- 解决的问题
- 解决方案
- MDC
- 具体逻辑
- yml
- logback-spring.xml
- TraceIdUtil操作工具类
- TraceIdFilter自定义过滤器
- GlobalExceptionHandler全局异常处理类
- TraceIdAspect切面
- UserController
- 测试验证
- 多线程处理
- MDCUtil工具类
- ThreadPoolMdcWrapper
- ContextTransferTaskDecorator
- ThreadPoolConfig
- UserController
- 测试验证
解决的问题
接口报错,如何快速定位问题?这个需要日志的辅助,一般错误日志中有详细的堆栈信息,具体是哪行代码报错,都可以看到。线程日志交差打印,要想快速定位问题,前提是要能够快速定位日志。
日志量一般都是很大的,如何能够从大量日志中找到自己需要的日志呢?
依赖原始的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}
- 向MDC中设置值:
假定已经解决了traceId
的存放问题,那么何时进行traceId
的存放呢?其实有多重实现思路,例如:过滤器、AOP、拦截器等等。
具体逻辑
yml
server:port: 8081spring:profiles:active: devapplication:name: springboot-logmain:allow-bean-definition-overriding: true
logback-spring.xml
java"><?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">--><!-- <!– 通过指定压缩文件名称,来确定分割文件方式–>--><!-- <fileNamePattern>${log.path}/error/log-error-%d{yyyy-MM-dd}.log%i.zip</fileNamePattern>--><!-- <!– 文件拆分大小 –>--><!-- <maxFileSize>1MB</maxFileSize>--><!-- <!–日志文件保留天数–>--><!-- <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操作工具类
java">/*** <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自定义过滤器
java">/*** <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全局异常处理类
java">@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切面
java">@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
java">@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工具类
java">/*** <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
java">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
java">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
java">@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
java">@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();}
}