SpringBoot log4j2日志追踪

关注

原创最新推荐文章于 2026-09-13 16:02:00 发布 2.3k 阅读 AI 写同款· GEO 优化 ›

log4j2(MDC)+Skywalking全局链路日志实现 1.问题目前：当线上出现问题需上kibana上去查询es上收集的log4j2日志。缺陷：在多个服务相互调用下，若出现Error级别日志时，无法快速准确定位到由哪个服务引起，只能根据日志时间模糊去定位。 log4j2没有配置传入参数，无法准确的复现错误。改进：优化：引入skywalking的traceId，能够显示出完整的链路调用。收集请求ip、请求参数、请求路径、返回状态码(属于业务状态码，并不是http状态码，例如Result类中的code)，返回数据等信息。定义log规范，在es上阅读详情

写在前面

本文只讨论非分布式体系的日志追踪，如果项目使用了微服务、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() => 移除所有MDC
get (String key) => 获取当前线程MDC中指定key的值
getContext() => 获取当前线程MDC的MDC
put(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>
        <!-- log4j2 start -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>
        <!-- log4j2 end -->

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} [%p] [%t] %c(%F:%L) - %m%n"/>-->
      <!-- 添加日志追踪traceId -->
      <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">

      <!--显示INFO级别日志-->
      <ThresholdFilter level="INFO" onMatch="ACCEPT"  onMismatch="DENY"/>
      <PatternLayout pattern="${layoutPattern}"/>

      <!--每个文件最多只能2G-->
      <Policies>
        <SizeBasedTriggeringPolicy size="2 GB" />
        <TimeBasedTriggeringPolicy modulate="true"/>
      </Policies>

      <!--删除超过15天的日志-->
      <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>

    <!--additivity="false"表示在该logger中输出的日志不会再延伸到父层logger。这里如果改为true，则会延伸到Root Logger，遵循Root Logger的配置也输出一次。-->
    <Logger name="org.springframework.boot.autoconfigure" level="DEBUG" additivity="true">
      <AppenderRef ref="stdout"/>
    </Logger>
    <!-- druid配置 start -->
    <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>
    <!-- druid配置 end -->

    <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 存在的问题

子线程中打印日志丢失traceId
kafka等中间件打印日志丢失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();
        }
    }
}

参考：