SpringBoot log4j2日志追踪

tech2026-01-11 19

写在前面

本文只讨论非分布式体系的日志追踪，如果项目使用了微服务、RPC等分布式框架的话，日志追踪有很成熟的框架，Google的Dapper,阿里的EagleEye，Twitter基于Google的Dapper论文开发的Zipkin

通过本文将了解到什么是MDC、MDC应用中存在的问题、如何解决存在的问题

MDC介绍

简介：

MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 、logback及log4j2 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据

API说明：

clear() => 移除所有MDCget (String key) => 获取当前线程MDC中指定key的值getContext() => 获取当前线程MDC的MDCput(String key, Object o) => 往当前线程的MDC中存入指定的键值对remove(String key) => 删除当前线程MDC中指定的键值对

优点：

代码简洁，日志风格统一，不需要在log打印中手动拼写traceId，即LOGGER.info("traceId:{} ", traceId)

这里使用log4j2打印日志

SpringBoot中使用log4j2可以参考SpringBoot log4j2日志之旅

pom.xml

<dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-web</artifactId> <exclusions> <exclusion> <artifactId>spring-boot-starter-logging</artifactId> <groupId>org.springframework.boot</groupId> </exclusion> <exclusion> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-tomcat</artifactId> </exclusion> </exclusions> </dependency> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-jetty</artifactId> </dependency>  <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-log4j2</artifactId> </dependency>

log4j2.xml

这里的关键是

<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%p] [%t] %c(%F:%L) - %m%n" />

%X{traceId}对应的就是MDC.put(Constants.TRACE_ID, traceId);

<?xml version="1.0" encoding="UTF-8"?> <Configuration monitorinterval="10" status="debug"> <Properties> <Property name="infoFile">./logs/info.log</Property> <Property name="infoFilePattern">./logs/info.log.%d{yyyy-MM-dd}_%i</Property> <Property name="errorFile">./logs/error.log</Property> <Property name="errorFilePattern">./logs/error.log.%d{yyyy-MM-dd}_%i</Property> <Property name="layoutPattern">%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] [%t] %c(%F:%L) - %m%n</Property> </Properties> <Appenders> <Console name="stdout">   <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%p] [%t] %c(%F:%L) - %m%n" /> </Console> <RollingFile fileName="${infoFile}" filePattern="${infoFilePattern}" name="infoAppender">  <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/> <PatternLayout pattern="${layoutPattern}"/>  <Policies> <SizeBasedTriggeringPolicy size="2 GB" /> <TimeBasedTriggeringPolicy modulate="true"/> </Policies>  <DefaultRolloverStrategy> <Delete basePath="./logs" maxDepth="2"> <IfLastModified age="30d" /> </Delete> </DefaultRolloverStrategy> </RollingFile> <RollingFile fileName="${errorFile}" filePattern="${errorFilePattern}" name="errorAppender"> <ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/> <PatternLayout pattern="${layoutPattern}"/> <Policies> <SizeBasedTriggeringPolicy size="2 GB" /> <TimeBasedTriggeringPolicy modulate="true"/> </Policies> </RollingFile> </Appenders> <Loggers>  <Logger name="org.springframework.boot.autoconfigure" level="DEBUG" additivity="true"> <AppenderRef ref="stdout"/> </Logger>  <logger name="druid.sql.Statement" level="debug" additivity="false"> <appender-ref ref="stdout"/> </logger> <logger name="druid.sql.ResultSet" level="debug" additivity="false"> <appender-ref ref="stdout"/> </logger>  <Root level="INFO"> <AppenderRef ref="stdout"/> <AppenderRef ref="infoAppender"/> <AppenderRef ref="errorAppender"/> </Root> </Loggers> </Configuration>

接口的日志追踪，traceId可以在拦截器中添加，也可以在过滤器中添加

{ @Bean public RequestContextListener requestContextListener() { return new RequestContextListener(); } @Override public void addInterceptors(InterceptorRegistry registry) { // 方式一：拦截器中添加traceId // registry.addInterceptor(new LogInterceptor()) // .addPathPatterns("/**") // .excludePathPatterns("/static/**", "/templates/**"); } @Bean public FilterRegistrationBean<LogTraceFilter> logTraceFilter() { // 方式二：过滤器中添加traceId final FilterRegistrationBean<LogTraceFilter> filterRegistrationBean = new FilterRegistrationBean<>(); final LogTraceFilter logTraceFilter = new LogTraceFilter(); filterRegistrationBean.setFilter(logTraceFilter); filterRegistrationBean.setName("logTraceFilter"); filterRegistrationBean.addUrlPatterns("/*"); filterRegistrationBean.setOrder(Ordered.HIGHEST_PRECEDENCE); return filterRegistrationBean; } }

方式一：拦截器添加traceId

package com.foo.bar.interceptor; import com.foo.bar.constant.Constants; import com.foo.bar.utils.TraceIdUtil; import org.slf4j.MDC; import org.springframework.web.servlet.HandlerInterceptor; import org.springframework.web.servlet.ModelAndView; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; /** * 日志追踪拦截器 * @author foo */ public class LogInterceptor implements HandlerInterceptor { @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { //如果有上层调用就用上层的ID String traceId = request.getHeader(Constants.TRACE_ID); if (traceId == null) { traceId = TraceIdUtil.getTraceId(); } MDC.put(Constants.TRACE_ID, traceId); return true; } @Override public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception { // Do nothing because of no business } @Override public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception { //调用结束后删除 MDC.remove(Constants.TRACE_ID); } }

方式二：过滤器添加traceId

package com.foo.bar.filter; import com.foo.bar.constant.Constants; import com.foo.bar.utils.TraceIdUtil; import org.slf4j.MDC; import org.springframework.web.filter.OncePerRequestFilter; import javax.servlet.FilterChain; import javax.servlet.ServletException; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import java.io.IOException; /** * @author: foo * @create: 2020-09-04 11:02 */ public class LogTraceFilter extends OncePerRequestFilter { @Override protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException { preHandle(request); filterChain.doFilter(request, response); afterCompletion(); } /** * 过滤前处理 * @param request 请求 * @return */ public void preHandle(HttpServletRequest request) { //如果有上层调用就用上层的ID String traceId = request.getHeader(Constants.TRACE_ID); if (traceId == null) { traceId = TraceIdUtil.getTraceId(); } MDC.put(Constants.TRACE_ID, traceId); } /** * 过滤后处理 */ public void afterCompletion() { //调用结束后删除 MDC.remove(Constants.TRACE_ID); } }

constant.java

package com.foo.bar.constant; /** * 常量类 * @author foo */ public class Constants { private Constants(){ throw new UnsupportedOperationException(); } /** * 日志追踪ID */ public static final String TRACE_ID = "traceId"; }

TraceIdUtil.java

package com.foo.bar.utils; import java.util.UUID; /** * traceId生成工具类 * @author foo */ public class TraceIdUtil { private TraceIdUtil() { throw new UnsupportedOperationException("Utility class"); } /** * 获取traceId * @return */ public static String getTraceId() { return UUID.randomUUID().toString().replace("-", "").toUpperCase(); } }

MDC 存在的问题

子线程中打印日志丢失traceIdkafka等中间件打印日志丢失traceId

子线程中打印日志丢失traceId

开启异步注解@EnableAsync

package com.foo.bar; import org.springframework.boot.SpringApplication; import org.springframework.boot.autoconfigure.SpringBootApplication; import org.springframework.scheduling.annotation.EnableAsync; /** * @author foo */ @EnableAsync @SpringBootApplication public class FooBarApplication { public static void main(String[] args) { SpringApplication.run(FooBarApplication.class, args); } }

配置异步线程池

package com.foo.bar.config; import lombok.extern.slf4j.Slf4j; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; import org.springframework.context.annotation.Primary; import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor; import java.util.concurrent.Executor; import java.util.concurrent.ThreadPoolExecutor; /** * 线程池配置 * * @author foo */ @Slf4j @Configuration public class ExecutorConfig { @Bean @Primary public Executor asyncServiceExecutor() { log.info("start asyncServiceExecutor"); ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor(); //配置核心线程数 executor.setCorePoolSize(10); //配置最大线程数 executor.setMaxPoolSize(200); //配置队列大小 executor.setQueueCapacity(99999); //配置线程池中的线程的名称前缀 executor.setThreadNamePrefix("async-service-"); // 设置拒绝策略：当pool已经达到max size的时候，如何处理新任务 // CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行 executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy()); //执行初始化 executor.initialize(); return executor; } }

测试Controller

package com.foo.bar.controller; import com.foo.bar.service.HelloService; import lombok.RequiredArgsConstructor; import lombok.extern.slf4j.Slf4j; import org.springframework.web.bind.annotation.GetMapping; import org.springframework.web.bind.annotation.RestController; /** * @author: foo * @create: 2020-09-04 14:15 */ @RestController @Slf4j @RequiredArgsConstructor public class HelloController { private final HelloService helloService; @GetMapping("/hello") public String hello(){ log.info("Hello World! hello无异步追踪！"); helloService.hello(); return "Hello World!"; } @GetMapping("/hello-async") public String helloAsync(){ log.info("Hello World! hello-async异步追踪！"); helloService.helloAsync(); return "Hello World!"; } }

测试Service

package com.foo.bar.service; import lombok.extern.slf4j.Slf4j; import org.springframework.scheduling.annotation.Async; import org.springframework.stereotype.Service; /** * @author: foo * @create: 2020-09-04 14:21 */ @Service @Slf4j public class HelloService { public void hello(){ log.info("进入hello业务方法"); } @Async public void helloAsync(){ log.info("进入helloAsync业务方法"); } }

测试结果：异步线程丢失了traceId

解决子线程日志打印丢失traceId问题

子线程在打印日志的过程中traceId将丢失，解决方式为重写线程池

线程池封装类：ThreadPoolExecutorMdcWrapper.java package com.foo.bar.config; import com.foo.bar.utils.ThreadMdcUtil; import lombok.extern.slf4j.Slf4j; import org.slf4j.MDC; import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor; import org.springframework.util.concurrent.ListenableFuture; import java.util.concurrent.Callable; import java.util.concurrent.Future; import java.util.concurrent.ThreadPoolExecutor; /** * spring线程池封装类 * @author foo */ @Slf4j public class ThreadPoolTaskExecutorWrapper extends ThreadPoolTaskExecutor { private void showThreadPoolInfo(String prefix){ ThreadPoolExecutor threadPoolExecutor = getThreadPoolExecutor(); if(null==threadPoolExecutor){ return; } log.info("{}, {},taskCount [{}], completedTaskCount [{}], activeCount [{}], queueSize [{}]", this.getThreadNamePrefix(), prefix, threadPoolExecutor.getTaskCount(), threadPoolExecutor.getCompletedTaskCount(), threadPoolExecutor.getActiveCount(), threadPoolExecutor.getQueue().size()); } @Override public void execute(Runnable task) { showThreadPoolInfo("1. do execute"); super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap())); } @Override public void execute(Runnable task, long startTimeout) { showThreadPoolInfo("2. do execute"); super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout); } @Override public Future<?> submit(Runnable task) { showThreadPoolInfo("1. do submit"); return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap())); } @Override public <T> Future<T> submit(Callable<T> task) { showThreadPoolInfo("2. do submit"); return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap())); } @Override public ListenableFuture<?> submitListenable(Runnable task) { showThreadPoolInfo("1. do submitListenable"); return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap())); } @Override public <T> ListenableFuture<T> submitListenable(Callable<T> task) { showThreadPoolInfo("2. do submitListenable"); return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap())); } } 线程traceId封装工具类：ThreadMdcUtil.java package com.foo.bar.utils; import com.foo.bar.constant.Constants; import org.slf4j.MDC; import java.util.Map; import java.util.concurrent.Callable; /** * 线程MDC工具类 * @author foo */ public class ThreadMdcUtil { public static void setTraceIdIfAbsent() { if (MDC.get(Constants.TRACE_ID) == null) { MDC.put(Constants.TRACE_ID, TraceIdUtil.getTraceId()); } } public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) { return () -> { if (context == null) { MDC.clear(); } else { MDC.setContextMap(context); } setTraceIdIfAbsent(); try { return callable.call(); } finally { 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(); } }; } }

说明【以封装Runnable为例】：

判断当前线程对应MDC的Map是否存在，存在则设置设置MDC中的traceId值，不存在则新生成，针对不是子线程的情况，如果是子线程，MDC中traceId不为null执行run方法

代码等同于以下写法，会更直观

public static Runnable wrap(final Runnable runnable, final Map<String, String> context) { return new Runnable() { @Override public void run() { if (context == null) { MDC.clear(); } else { MDC.setContextMap(context); } setTraceIdIfAbsent(); try { runnable.run(); } finally { MDC.clear(); } } }; }

重新返回的是包装后的Runnable，在该任务执行之前【runnable.run()】先将主线程的Map设置到当前线程中【即MDC.setContextMap(context)】，这样子线程和主线程MDC对应的Map就是一样的了

修改ExecutorConfig.java的asyncServiceExecutor方法，将ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor()改为ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutorWrapper()，如下所示：

package com.foo.bar.config; import lombok.extern.slf4j.Slf4j; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; import org.springframework.context.annotation.Primary; import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor; import java.util.concurrent.Executor; import java.util.concurrent.ThreadPoolExecutor; /** * 线程池配置 * * @author foo */ @Slf4j @Configuration public class ExecutorConfig { @Bean @Primary public Executor asyncServiceExecutor() { log.info("start asyncServiceExecutor"); ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutorWrapper(); //配置核心线程数 executor.setCorePoolSize(10); //配置最大线程数 executor.setMaxPoolSize(200); //配置队列大小 executor.setQueueCapacity(99999); //配置线程池中的线程的名称前缀 executor.setThreadNamePrefix("async-service-"); // 设置拒绝策略：当pool已经达到max size的时候，如何处理新任务 // CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行 executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy()); //执行初始化 executor.initialize(); return executor; } }

重新测试异步线程日志追踪，异步子线程中的traceId与父线程程一致了，OK。

kafka等中间件打印日志丢失traceId

解决方式可以通过AOP切入onMessage这个方法

package com.foo.bar.aspect; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.aspectj.lang.annotation.Pointcut; import org.slf4j.MDC; import org.springframework.stereotype.Component; import com.foo.bar.constant.Constants; import com.foo.bar.utils.TraceIdUtil; import lombok.RequiredArgsConstructor; import lombok.extern.slf4j.Slf4j; /** * MDC日志kafka切面 * * @author foo * @date 2020/9/7 14:36 */ @Aspect @Component @Slf4j @RequiredArgsConstructor public class MdcKafkaAspect { /** * 定义切入点 * 通过@Pointcut注解声明频繁使用的切点表达式 */ @Pointcut("execution(* onMessage(..)) && target(org.springframework.kafka.listener.MessageListener)") public void messageListener() { // This func is intentionally empty. Nothing special is needed here. } @Around(value = "messageListener()") public void wrapOnMessage(ProceedingJoinPoint joinPoint) throws Throwable { try { MDC.put(Constants.TRACE_ID, TraceIdUtil.getTraceId()); joinPoint.proceed(); } finally { MDC.clear(); } } }

参考：

springboot线程池的使用和扩展SpringBoot+MDC实现全链路调用日志跟踪SpringBoot log4j2日志之旅分布式系统中如何优雅地追踪日志（原理篇）

分布式集群环境下调用链路追踪（Google Dapper）

最新回复(0)