SpringAOP + Logback + MDC实现全链路日志追踪

1、背景

博主所在的公司因为有权限管理和架构规范，服务都部署到云上，只能通过日志系统查看日志。但是日志是通过 kafka 采集的，所有节点的日志都堆在一起，要想在像海一样的日志里面查询关键信息和调用链路比较困难。因此，实现全链路日志追踪显得非常重要。

2、方案调研

在 Spring Boot 中实现全链路日志跟踪，通常涉及到在请求处理的整个过程中（从前端到后端，再到可能的后端服务之间的调用）传递一个唯一的跟踪ID（如Trace ID）。这个 ID 可以用于在日志中标记和搜索特定请求的日志条目，从而实现全链路的日志跟踪。

以下是一些实现全链路日志跟踪的常用方法：

2.1 使用 MDC(Mapped Diagnostic Context)

MDC 是 Log4j 和 Logback 等日志框架提供的一个功能，允许你在日志消息中嵌入上下文信息。你可以在请求开始时生成一个 Trace ID,并将其放入 MDC,然后在后续的日志记录中使用这个 ID.

示例（使用 Logback）：

MDC.put("traceId", traceId);  

// 记录日志，此时log中会自动包含traceId  
logger.info("Processing request...");  

// ... 在请求处理过程中保持MDC中的traceId不变  

// 请求处理完成后，可以选择性地清除MDC中的traceId  
MDC.remove("traceId");

2.2 使用 Spring Cloud 的分布式追踪

如果你的应用是微服务架构，并且已经在使用 Spring Cloud,那么可以使用 Spring Cloud Sleuth 来实现分布式追踪。Sleuth 会在 HTTP 请求头中自动注入 Trace ID 和 Span ID,并在日志中输出这些信息。

你需要在项目的依赖管理文件中添加 Spring Cloud Sleuth 的依赖，并在配置文件中启用相关功能。

2.3 自定义拦截器和过滤器

你可以编写自定义的拦截器（用于 SpringMVC）或过滤器（用于 Servlet API），在请求进入和退出时生成和传递 Trace ID.拦截器和过滤器可以访问请求和响应对象，因此可以在 HTTP 头中注入或提取 Trace ID.

示例（使用 SpringMVC 拦截器）：

@Component  
public class TraceInterceptor implements HandlerInterceptor {  

    @Override  
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {  

        // 从请求头中提取或生成Trace ID  

        // ...  

        // 将Trace ID放入MDC或请求属性中  

        return true;  
    }  

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {  

        // 清除MDC中的Trace ID（如果需要）  

    }  

}

2.4 使用 OpenTracing 或 Zipkin 等第三方追踪系统

这些系统提供了更强大的分布式追踪功能，包括可视化的追踪数据、服务依赖图等。它们通常与 Spring Cloud Sleuth 集成良好，可以很容易地集成到你的 Spring Boot 应用中。

2.5 在日志格式中包含 Trace ID

无论你选择哪种方法生成和传递 Trace ID,都应该在日志格式中包含这个 ID.这样，在查看或搜索日志时，就可以很容易地找到与特定请求相关的所有日志条目。

2.6 跨服务传递 Trace ID

如果你的应用调用了其他后端服务，你需要在调用这些服务时传递 Trace ID.这通常可以通过在 HTTP 请求头中添加自定义头来实现。在接收端，你可以从请求头中提取这个 ID,并将其放入 MDC 或日志中。

3、方案选择

因为博主所做项目主要是 SpringBoot 框架，不涉及 SpringCloud,考虑到适配性和集成难度，最后选择通过 SpringAOP + Logback + MDC 实现全链路日志追踪。

4、方案实施

4.1 添加依赖

以 Maven 为例，你可能需要添加以下依赖：

<!-- Spring AOP --> 
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId> 
</dependency> 

<!-- Logback Classic --> 
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId> 
</dependency> 

<!-- Spring Boot Starter Logging (通常会包含Logback的依赖) --> 
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-logging</artifactId> 
</dependency>

4.2 配置 Logback

在 logback-spring.xml（或 logback.xml ）中配置 Logback 以包含 MDC 中的 traceId.例如：

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - [%X{traceId}] - %msg%n</pattern>
        </encoder>
    </appender> 
    
    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root> 
</configuration>

这里的 %X{traceId} 将会输出 MDC 中名为 traceId 的值。

4.3 创建 AOP 切面

创建一个 Spring AOP 切面来拦截方法调用，并在方法调用前后设置和清除 MDC 中的 traceId.

@Aspect  
@Component  
public class TraceAspect {  
  
    @Pointcut("execution(* com.yourpackage..*.*(..))")  
    public void allMethods() {}  
  
    @Before("allMethods()")  
    public void beforeAdvice(JoinPoint joinPoint) {  
        // 生成traceId，这里只是简单示例，实际应用中可能需要更复杂的逻辑  
        String traceId = UUID.randomUUID().toString();  
        MDC.put("traceId", traceId);  
    }  
  
    @After("allMethods()")  
    public void afterAdvice() {  
        // 清除MDC中的traceId  
        MDC.clear();  
    }  
}

注意：上面的示例使用了 @Before 和 @After 注解来分别在方法调用前和调用后设置和清除 MDC 中的 traceId.但是，在真实的应用场景中，你可能希望在 HTTP 请求的开始和结束时设置和清除 traceId,这时你可能需要使用 @Around 注解，并在 AOP 切面中处理 HTTP 请求。

以我实际项目中代码为例，定义一个 Web 全局拦截器，拦截 HTTP 请求中携带的 traceId,如果没有携带就生成一个随机 ID,并在请求前后处理 traceId.

import org.slf4j.MDC;
import org.springframework.stereotype.Component;

import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.Optional;
import java.util.UUID;

@Component
public class MDCFilter implements Filter {
    private static final String REQUEST_ID_HEADER = "requestId";
    private static final String REQUEST_ID = "requestId";

    @Override
    public void init(FilterConfig filterConfig) {
    }

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        HttpServletRequest request = (HttpServletRequest) servletRequest;
        HttpServletResponse response = (HttpServletResponse) servletResponse;
        String requestId = request.getHeader(REQUEST_ID_HEADER);
        String requestIdMDC = Optional.ofNullable(requestId).orElseGet(() -> UUID.randomUUID().toString());
        response.setHeader(REQUEST_ID_HEADER, requestIdMDC);
        MDC.put(REQUEST_ID, requestIdMDC);
        try {
            filterChain.doFilter(request,response);
        } finally {
            MDC.clear();
        }
    }

    @Override
    public void destroy() {
    }
}

4.4 多线程情况

上述处理没有考虑多线程的场景，而 MDC(Mapped Diagnostic Context)是基于线程的，它为每个线程维护一个独立的映射。这意味着，如果在不同的线程中处理相同的请求，并且你希望这些线程共享相同的 Trace ID,你需要确保正确地将 Trace ID 从一个线程传递到另一个线程。

解决方式：采用 TaskDecorator 的线程任务装饰器方式为线程池的线程提供 traceId 的传递操作。

4.4.1 定义任务装饰器

import lombok.NonNull;
import org.slf4j.MDC;
import org.springframework.core.task.TaskDecorator;
import org.springframework.util.ObjectUtils;

import java.util.Map;

public class MDCTaskDecorator implements TaskDecorator {
    @Override
    public @NonNull Runnable decorate(@NonNull Runnable runnable) {
        // 此时获取的是父线程的上下文数据
        Map<String, String> contextMap = MDC.getCopyOfContextMap();
        return () -> {
            try {
                if (!ObjectUtils.isEmpty(contextMap)) {
                    MDC.setContextMap(contextMap);
                }
                runnable.run();
            } finally {
                // 清除子线程的，避免内存溢出，就和ThreadLocal.remove()一个原因
                MDC.clear();
            }
        };
    }
}

4.4.2 定义线程池

@Configuration
public class PoolConfig {
    @Bean("taskExecutor")
    public Executor taskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        //配置核心线程数
        executor.setCorePoolSize(5);
        //配置最大线程数
        executor.setMaxPoolSize(10);
        //配置队列大小
        executor.setQueueCapacity(100);
        //配置线程池中的线程的名称前缀
        executor.setThreadNamePrefix("mdc-trace-");
        // 异步MDC
        executor.setTaskDecorator(new MDCTaskDecorator());
        //执行初始化
        executor.initialize();
        return executor;
    }
}

4.4.3 使用线程池

@Resource
  @Qualifier("taskExecutor")
  private Executor executor;

  @PostMapping("/pool")
  public String pool() throws Exception{
      CompletableFuture<String> future = CompletableFuture.supplyAsync(() -> {
          log.info("线程池里面");
          try{
              Thread.sleep(1000);
          } catch (Exception ignored){}

          return "";
      }, executor);
      future.thenApplyAsync( value ->{
          log.info("线程池组合操作");
          try{
              Thread.sleep(1000);
          } catch (Exception ignored) {}
          return value + "1";
      }, executor);
      return future.get();
  }

或者异步调用时使用 @Async("taskExecutor").

5、成果展示

6、总结

通过 SrpingAOP + Logback + MDC 可以实现简单的全链路日志追踪，并且考虑了多线程的情形，可以为我们排查问题提供很大的帮助，特别是业务逻辑链路较长，日志量较大时，能快速定位问题，并提高系统的监控和统计能力。