从零开始改造spring项目-为每个请求添加独一无二的id

1.新建项目

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
</dependency>
<!--lombok-->
<dependency>
    <groupId>org.projectlombok</groupId>
    <artifactId>lombok</artifactId>
    <optional>true</optional>
</dependency>
复制代码

除了spring的web依赖包外，添加一个lombok，方便编码。

2.编写controller方法

@RestController
public class TestController {
    @GetMapping("hello")
    public String hello(){        
        log.info("this is hello 1");
        log.info("this is hello 2");
        log.info("this is hello 3");
        return "hello";
    }
}
复制代码

这个时候一个简单的rest接口已经完成了，我们可以先看看日志的效果。

2019-10-23 10:45:10.917  INFO 1146 --- [nio-8080-exec-1] c.e.demo.controller.TestController       : this is hello 1
2019-10-23 10:45:10.917  INFO 1146 --- [nio-8080-exec-1] c.e.demo.controller.TestController       : this is hello 2
2019-10-23 10:45:10.917  INFO 1146 --- [nio-8080-exec-1] c.e.demo.controller.TestController       : this is hello 3
复制代码

从这个日志中，我们根本无法区分单独的请求。如果同一时间有2到3个请求过来的话，那么你还能分得清那个对那个么？所以这就是今天要改造的地方。

改造思路

其实要改造的话其实很简单，我们可以在每个controller入口处，生成唯一的uuid，并传递下去。这样的话缺点就是对代码干扰太大，每个方法都要多加一个参数。

那么我们能不能把这个参数存在一个统一的地方，需要打印日志的时候，直接去取呢？大家应该可以想到了，用ThreadLocal类。其实到这儿思路已经对了，不过日志框架也想到了这个问题，他们已经封装好了现成的功能，就是日志框架中的MDC

1.首先将日志的id添加进MDC中

@Component
public class TraceIdInterceptor extends HandlerInterceptorAdapter {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String traceId = getTraceId(request);
        MDC.put("traceId", traceId);
        //将traceId添加进响应头
        response.addHeader("traceId",traceId);
        return true;
    }

    private String getTraceId(HttpServletRequest request){
        return String.format("%s - %s",request.getRequestURI(), UUID.randomUUID());
    }
}

@Component
public class GlobalWebMvcConfigurer implements WebMvcConfigurer {

    @Autowired
    private TraceIdInterceptor traceIdInterceptor;

    @Override
    /*
      traceId 拦截器需要在最开始执行
     */
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(traceIdInterceptor).order(0);
    }

}
复制代码

我们使用一下Spring的拦截器功能。在请求开始之前，将请求id添加进MDC。

2.修改日志的配置文件

新建一个logback-spring.xml文件添加如下内容

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="LOG_PATTERN"
              value="%d{yyyy-MM-dd} %d{HH:mm:ss.SSS} [%-5level] [%X{traceId}] [%thread] %logger{36} %F.%L %msg%n">
    </property>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
        <!-- 控制台打印INFO及以上级别的日志 -->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>

    <root>
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>
复制代码

在日志的格式LOG_PATTERN中，添加%X{traceId} ，这样日志在打印的时候便会去MDC中取出traceid，放在这儿。现在我们可以看看效果。

2019-10-23 11:02:46.649 [INFO ] [/hello - 79ec561a-ef5e-4dc5-91cc-b2143fa3dbd3] [http-nio-8080-exec-1] c.e.demo.controller.TestController TestController.java.18 this is hello 1
2019-10-23 11:02:46.649 [INFO ] [/hello - 79ec561a-ef5e-4dc5-91cc-b2143fa3dbd3] [http-nio-8080-exec-1] c.e.demo.controller.TestController TestController.java.19 this is hello 2
2019-10-23 11:02:46.650 [INFO ] [/hello - 79ec561a-ef5e-4dc5-91cc-b2143fa3dbd3] [http-nio-8080-exec-1] c.e.demo.controller.TestController TestController.java.20 this is hello 3
2019-10-23 11:02:47.612 [INFO ] [/hello - 2ac7450f-40f5-441c-8e10-9b937c006484] [http-nio-8080-exec-2] c.e.demo.controller.TestController TestController.java.18 this is hello 1
2019-10-23 11:02:47.612 [INFO ] [/hello - 2ac7450f-40f5-441c-8e10-9b937c006484] [http-nio-8080-exec-2] c.e.demo.controller.TestController TestController.java.19 this is hello 2
2019-10-23 11:02:47.612 [INFO ] [/hello - 2ac7450f-40f5-441c-8e10-9b937c006484] [http-nio-8080-exec-2] c.e.demo.controller.TestController TestController.java.20 this is hello 3

复制代码

可以看到，两个请求通过traceId可以很清楚的区分开了。这样我们在排查问题的时候，可以通过响应头里面的traceId，直接查找到相关日志，非常方便。

进阶版traceId

之前说过traceId的实现思路是通过ThreadLocal来实现的。使用ThreadLocal有一个前提就是一个请求进来始终是一个线程在处理。如果用到spring中的异步方法，traceId就会失效了。

我们可以做个实验

//编写一个service类
public class Service {
    @Async
    public void run(){
        log.info("this is service run!");
    }
}

//在hello方法中调用service的run方法
@GetMapping("hello")
public String hello(){
    log.info("this is hello 1");
    log.info("this is hello 2");
    log.info("this is hello 3");
    service.run();
    return "hello";
}
复制代码

可以看的打印出来的日志

2019-10-23 11:12:23.265 [INFO ] [/hello - 96b31833-e8e6-46c5-8459-d423309d1488] [http-nio-8080-exec-1] c.e.demo.controller.TestController TestController.java.22 this is hello 1
2019-10-23 11:12:23.266 [INFO ] [/hello - 96b31833-e8e6-46c5-8459-d423309d1488] [http-nio-8080-exec-1] c.e.demo.controller.TestController TestController.java.23 this is hello 2
2019-10-23 11:12:23.267 [INFO ] [/hello - 96b31833-e8e6-46c5-8459-d423309d1488] [http-nio-8080-exec-1] c.e.demo.controller.TestController TestController.java.24 this is hello 3
2019-10-23 11:12:23.278 [INFO ] [] [task-1] com.example.demo.controller.Service Service.java.17 this is service run!
复制代码

其实也很简单，只要对异步线程池跑的对象稍作封装即可。

@EnableAsync
@Configuration
public class AsyncConfiguration {

    @Autowired
    private AppConfig config;

    @Bean("async")
    public Executor taskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        //设置核心线程数量
        executor.setCorePoolSize(config.getAsync().getCorePoolSize());
        //设置最大线程数量
        executor.setMaxPoolSize(config.getAsync().getMaxPoolSize());
        //设置队列最大长度
        executor.setQueueCapacity(config.getAsync().getQueueCapacity());
        //设置线程空闲时间
        executor.setKeepAliveSeconds(config.getAsync().getKeepLiveSeconds());
        //设置线程前缀
        executor.setThreadNamePrefix("async-");
        //设置拒绝策略
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        //设置线程装饰器
        executor.setTaskDecorator(runnable -> ThreadMdcUtils.wrapAsync(runnable, MDC.getCopyOfContextMap()));
        return executor;
    }
}

public class ThreadMdcUtils {
    public static Runnable wrapAsync(Runnable task, Map<String,String> context){
        return () -> {
            if(context==null){
                MDC.clear();
            }else {
                MDC.setContextMap(context);
            }
            if(MDC.get(Constant.TraceId)==null){
                MDC.put(Constant.TraceId,UUIDUtils.randomUUID());
            }
            try {
                task.run();
            }finally {
                MDC.clear();
            }
        };
    }
}
复制代码

这样的话，即便调用异步方法，也能获得统一的日志id。