日志链路追踪_MDC 日志全链路跟踪

在我们的系统中，曾经遇到这么一个问题：一个公共逻辑的方法，有很多个方法入口会调用到。当多个操作源头同时操作，查日志的时候，无法通过公共方法里面的日志内容反推出来源，给我们带来一定的麻烦。曾经想过改造公共方法和所有的调用，加上来源字段，但是由于逻辑比较深，改造起来需要改很多代码，就迟迟没有动手，直到偶然在网上发现了MDC这个东西，才解决掉。这里记录下使用过程，比较简单。

这里我们是用的SpringBoot。

首先贴一下我们正常日志打印的代码

@RestController
@RequestMapping("/user")
public class UserController {


    private static final Logger LOGGER = LoggerFactory.getLogger(UserController.class);


    @Resource
    private UserService userService;


    @RequestMapping("/add/{code}/{name}/{address}/")
    public String add(@PathVariable String code, @PathVariable String name, @PathVariable String address) {
        LOGGER.info("开始执行service");
        userService.save(code, name, address);
        LOGGER.info("执行service完成");
        return "OK";
    }
}

@Service
public class UserService {


    private static final Logger LOGGER = LoggerFactory.getLogger(UserService.class);


    @Resource
    private UserMapper userMapper;
    @Resource
    private UserExtService userExtService;


    //controller入口，这里选择了User事务，所以配置了mainTransactionManager
    @Transactional(transactionManager = "mainTransactionManager")
    public void save(String code, String name, String address) {
        //1
        LOGGER.info("{}、这里可能是一些参数校验之类的工作", 1);
        userMapper.addUser(code, name);
        //2
        LOGGER.info("{}、sql出错了或者保存后的一些操作出现了问题", 2);
        userExtService.addExt(code, address);
        //3
        LOGGER.info("{}、sql出错了或者保存后的一些操作出现了问题", 3);
    }
}

@Service
public class UserExtService {


    private static final Logger LOGGER = LoggerFactory.getLogger(UserExtService.class);


    @Resource
    private UserExtMapper userExtMapper;


    /**
     * 指定事务管理器：testTransactionManager
     * 开启新的事务
     */
    @Transactional(transactionManager = "testTransactionManager", propagation = Propagation.REQUIRES_NEW)
    public void addExt(String code, String address) {
        //4
        LOGGER.info("{}、这里可能是一些参数校验之类的工作", 4);
        userExtMapper.addExt(code, address);
        //5
        LOGGER.info("{}、sql出错了或者保存后的一些操作出现了问题", 5);
    }
}

代码比较简单，这里主要为了介绍日志链路，就不贴其他的代码了，想看其他代码，可以看我的另外一篇介绍mybatis集成的文章SpringBoot+Mybatis多数据源集成

其实直接这样，日志也能打印出来的，只不过是在并发高的时候，日志里面的序号（1、2、3、4、5）不知道谁和谁一组而已。现在我们就在处理这个问题。

这里提供2个方案

方案一，利用拦截器

public class LogInterceptor implements HandlerInterceptor {


    private static final String TRACE_ID = "traceId";


    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        //设置traceId
        MDC.put(TRACE_ID, "LogInterceptor-" + UUIDUtil.getUUID());
        return true;
    }


    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
    }


    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        //清空TraceId
        MDC.remove(TRACE_ID);
        MDC.clear();
    }
}

@SpringBootConfiguration
public class WebConfig extends WebMvcConfigurationSupport {
    @Bean
    public LogInterceptor logInterceptor() {
        return new LogInterceptor();
    }


    @Override
    protected void addInterceptors(InterceptorRegistry registry) {
        super.addInterceptors(registry);
        //增加日志拦截器
        registry.addInterceptor(logInterceptor());
    }
}

#日志配置，主要配置一下日志格式，把我们的traceId打印出来（通用）
logging.file.path=/boot
logging.file.name=log.log
logging.level.root=info
logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss} {%thread} [%X{traceId}] %5level %logger- %msg%n
logging.pattern.file=%d{yyyy-MM-dd HH:mm:ss} {%thread} [%X{traceId}] %5level %logger- %msg%n

这样就好了，看下我们的日志

2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.example.boot.controller.UserController- 开始执行service
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.example.boot.service.UserService- 1、这里可能是一些参数校验之类的工作
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.example.boot.service.UserService- 2、sql出错了或者保存后的一些操作出现了问题
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.zaxxer.hikari.HikariDataSource- HikariPool-2 - Starting...
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.zaxxer.hikari.HikariDataSource- HikariPool-2 - Start completed.
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.example.boot.service.UserExtService- 4、这里可能是一些参数校验之类的工作
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.example.boot.service.UserExtService- 5、sql出错了或者保存后的一些操作出现了问题
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.example.boot.service.UserService- 3、sql出错了或者保存后的一些操作出现了问题
2022-04-10 18:03:29 {http-nio-8080-exec-1} [LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1]  INFO com.example.boot.controller.UserController- 执行service完成


可以看到traceId都是LogInterceptor-e9b2a1fb993541c8acad61c0f01da3d1，这样就方便了我们来溯源。
有新的请求过来，会有新的traceId

方案二，利用aop

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

@Aspect
@Component
public class LogAop {


    private static final String TRACE_ID = "traceId";


    /**
     * RestController注解 切点
     */
    @Pointcut("@within(org.springframework.web.bind.annotation.RestController)")
    public void controller() {
    }


    @Around("controller()")
    public Object mdc(ProceedingJoinPoint point) throws Throwable {
        try {
            //设置traceId
            MDC.put(TRACE_ID, "AOP-" + UUIDUtil.getUUID());
            return point.proceed();
        } finally {
            //清空TraceId
            MDC.remove(TRACE_ID);
            MDC.clear();
        }
    }
}

2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.example.boot.controller.UserController- 开始执行service
2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.example.boot.service.UserService- 1、这里可能是一些参数校验之类的工作
2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.example.boot.service.UserService- 2、sql出错了或者保存后的一些操作出现了问题
2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.zaxxer.hikari.HikariDataSource- HikariPool-2 - Starting...
2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.zaxxer.hikari.HikariDataSource- HikariPool-2 - Start completed.
2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.example.boot.service.UserExtService- 4、这里可能是一些参数校验之类的工作
2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.example.boot.service.UserExtService- 5、sql出错了或者保存后的一些操作出现了问题
2022-04-10 18:19:17 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.example.boot.service.UserService- 3、sql出错了或者保存后的一些操作出现了问题
2022-04-10 18:19:18 {http-nio-8080-exec-2} [AOP-e0ad2513fbb04383ab94387e8594cff9]  INFO com.example.boot.controller.UserController- 执行service完成


可以看到，所有的traceId都是AOP-e0ad2513fbb04383ab94387e8594cff9，同拦截器方式一样的效果

OK！使用起来都比较简单，大家选用适合自己的即可。但是也有几点需要注意的，这里提醒下

1. MDC的traceId是利用的ThreadLocal，在使用完成后，一定要清理掉，避免内存泄漏。
2. MDC最终使用的ThreadLocal，线程级别的，如果在主线程里面有子线程的情况，注意为自线程设置相同的traceId。MDC.get("traceId")
3. 如果存在其他方法调用入口方法的情况，也要先获取到已经设置过的traceId再进行设置，避免覆盖老的traceId值。比如controller调用controller的情况，被调用的controller会直接设置成新的traceId。

over~~