SpringBoot项目使用slf4j的MDC日志打点功能

系统管理员 2024-03-16 13:43 12阅读 0赞

## SpringBoot项目使用slf4j的MDC日志打点功能 ##

物料准备：

1.自定义1个线程MDC打点工具类

2.配置logback打印MDC打点的traceId

3.配置webMVC使用MDC打点

4.配置ThreadPoolTaskExecutor使用MDC打点

5.配置HttpClient使用MDC打点

6.测试MDC日志打点效果

### 线程mdc打点工具类代码 ###

package cn.ath.knowwikibackend.mdc;
    
    
    import cn.hutool.core.lang.UUID;
    import org.slf4j.MDC;
    
    import java.util.Map;
    import java.util.concurrent.Callable;
    
    /**
     * 线程mdc打点工具类
     */
    public class ThreadMdcUtil {
        
    
        public static void setTRaceIdIfAbsent() {
        
            if (MDC.get("traceId") == null) {
        
                MDC.put("traceId", UUID.fastUUID().toString());
            }
        }
    
        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 {
        
                    //最终通过 callable.call执行线程任务
                    return callable.call();
                } finally {
        
                    MDC.clear();
                }
            };
        }
    
        public static Runnable wrap(final Runnable runnable,final Map<String,String> context){
        
            return ()->{
        
              if (context==null){
        
                  MDC.clear(); //mdc上下文为空 就清掉mdc
              }else {
        
                  MDC.setContextMap(context);  // mdc上下文不为空,要设置上下文为 context
              }
              setTRaceIdIfAbsent(); //设置mdc 记录traceId
              try {
        
                  //最终通过 runnable.run 执行线程任务
                  runnable.run();
              }finally {
        
                  MDC.clear();
              }
            };
        }
    }

### 配置logback 输出的日志格式，要输出mdc里定义的traceId ###

logging:
      file:
        path: ${
        user.home}/.${
        spring.application.name}/log/
      logback:
        rollingpolicy:
          max-file-size: 15MB
          max-history: 10
      pattern: # 注意这里配置的 [%X{traceId}] 即输出mdc打点的traceId值
        console: "%date  %level [%thread] [%X{traceId}] %logger{10} [%file : %line] %msg%n"
        file: "%date  %level [%thread] [%X{traceId}] %logger{10} [%file : %line] %msg%n"
      level:
        cn.ath.knowwikibackend.rest: info

### 配置webMVC使用MDC打点 ###

#### 定义MvcTraceInterceptor，来拦截http请求进行mdc打点 ####

package cn.ath.knowwikibackend.mdc;
    
    
    import cn.hutool.core.lang.UUID;
    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;
    
    /**
     * mvc trace拦截器，作用是 实现trace打点
     */
    public class MvcTraceInterceptor implements HandlerInterceptor {
        
        @Override
        public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        
            //在请求头里拿一个 traceId ,拿不到就创建1个 traceId
            String traceId = request.getHeader("traceId");
            if (traceId==null){
        
                traceId = UUID.fastUUID().toString();
            }
            // traceId记录到mdc中
            MDC.put("traceId",traceId);
            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 {
        
            //1个http请求 后台处理完毕后 ,从mdc中移除 traceId
            MDC.remove("traceId");
        }
    }

#### 使用自定义的MvcTraceInterceptor ####

package cn.ath.knowwikibackend.mdc;
    
    
    import org.springframework.context.annotation.Configuration;
    import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
    import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
    @Configuration
    public class MvcMdcConfig implements WebMvcConfigurer {
        
    
        /**
         * 配置spring mvc启用 mvc trace拦截器，实现trace打点
         * @param registry InterceptorRegistry
         */
        @Override
        public void addInterceptors(InterceptorRegistry registry) {
        
            registry.addInterceptor(new MvcTraceInterceptor())
                    .addPathPatterns("/**");
        }
    }

### 配置ThreadPoolTaskExecutor使用MDC打点 ###

package cn.ath.knowwikibackend.mdc;
    
    import org.slf4j.MDC;
    import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
    import java.io.Serializable;
    import java.util.concurrent.*;
    /**
     * 异步线程池 的mdc 包装器，作用是 让 async 异步任务 实现trace打点
     */
    public class AsyncThreadPoolMdcWrapper extends ThreadPoolTaskExecutor implements Serializable {
        
    
        private static final long serialVersionUID = -1530245553055682935L;
    
        @Override
        public void execute(Runnable task) {
        
            // Runnable 类型的线程运行时  进行 mdc 打点记录
            super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
        }
    
        @Override
        public <T> Future<T> submit(Callable<T> task) {
        
            // Callable 类型的线程运行时  进行 mdc 打点记录
            return super.submit(ThreadMdcUtil.wrap(task,MDC.getCopyOfContextMap()));
        }
    
        @Override
        public Future<?> submit(Runnable task) {
        
            //  Runnable 类型且返回Future的 线程运行时  进行 mdc 打点记录
            return super.submit(ThreadMdcUtil.wrap(task,MDC.getCopyOfContextMap()));
        }
    }

### 配置ApacheHttpClient使用MDC打点 ###

package cn.ath.knowwikibackend.mdc;
    
    import lombok.extern.slf4j.Slf4j;
    import org.apache.http.Header;
    import org.apache.http.HttpException;
    import org.apache.http.HttpRequest;
    import org.apache.http.HttpRequestInterceptor;
    import org.apache.http.protocol.HttpContext;
    import org.slf4j.MDC;
    import org.springframework.stereotype.Component;
    import java.io.IOException;
    
    /**
     * 自定义 HttpRequestInterceptor，
     * 这里可以对外发的http请求 追加请求头/请求参数之类的配置
     *
     * 这里 在 Header 里追加上本应用的traceId ,便于全局排查请求日志
     */
    @Component
    @Slf4j
    public class HttpClientTracedInterceptor implements HttpRequestInterceptor {
        
    
        @Override
        public void process(HttpRequest httpRequest, HttpContext httpContext) throws HttpException, IOException {
        
            //从mdc 中取出traceId 然后追加到 外发的http请求头里
            String traceId = MDC.get("traceId");
            if (traceId != null){
        
                httpRequest.addHeader("traceId",traceId);
            }
            
            //打印出所有的http请求头
            for (Header header : httpRequest.getAllHeaders()) {
        
                log.info("req header item---->{}",header);
            }
        }
    }

### 测试MDC日志打点效果 ###

#### 修改之前的异步线程池使用AsyncThreadPoolMdcWrapper 替换掉默认的ThreadPoolTaskExecutor ####

@Configuration
    public class AsyncConfig {
        
         @Bean("asyncCountTestTaskExecutor")
        public AsyncThreadPoolMdcWrapper asyncCountTaskTest(){
        
            AsyncThreadPoolMdcWrapper executor = new AsyncThreadPoolMdcWrapper();
            //核心线程数5：线程池创建时候初始化的线程数
            executor.setCorePoolSize(5);
            //最大线程数10：线程池最大的线程数，只有在缓冲队列满了之后才会申请超过核心线程数的线程
            executor.setMaxPoolSize(10);
            //缓冲队列100：用来缓冲执行任务的队列
            executor.setQueueCapacity(100);
            //允许线程的空闲时间60秒：当超过了核心线程出之外的线程在空闲时间到达之后会被销毁
            executor.setKeepAliveSeconds(60);
            //线程池名的前缀：设置好了之后可以方便我们定位处理任务所在的线程池
            executor.setThreadNamePrefix("countTestTaskAsync-");
            //线程池满了后新任务由 任务发起者的线程执行
            RejectedExecutionHandler callerRunsPolicy = new ThreadPoolExecutor.CallerRunsPolicy();
            executor.setRejectedExecutionHandler(callerRunsPolicy);
            executor.initialize();
            return executor;
        }
    
        @Bean("asyncVoidTestTaskExecutor")
        public AsyncThreadPoolMdcWrapper asyncVoidTaskTest(){
        
            AsyncThreadPoolMdcWrapper executor = new AsyncThreadPoolMdcWrapper();
            //核心线程数5：线程池创建时候初始化的线程数
            executor.setCorePoolSize(5);
            //最大线程数10：线程池最大的线程数，只有在缓冲队列满了之后才会申请超过核心线程数的线程
            executor.setMaxPoolSize(10);
            //缓冲队列100：用来缓冲执行任务的队列
            executor.setQueueCapacity(100);
            //允许线程的空闲时间60秒：当超过了核心线程出之外的线程在空闲时间到达之后会被销毁
            executor.setKeepAliveSeconds(60);
            //线程池名的前缀：设置好了之后可以方便我们定位处理任务所在的线程池
            executor.setThreadNamePrefix("voidTestTaskAsync-");
            //线程池满了后新任务由 任务发起者的线程执行
            RejectedExecutionHandler callerRunsPolicy = new ThreadPoolExecutor.CallerRunsPolicy();
            executor.setRejectedExecutionHandler(callerRunsPolicy);
            executor.initialize();
            return executor;
        }
    }

#### 在API接口中测试 ####

@Slf4j
    @RestController
    @RequestMapping("/third")
    public class TestApi {
        
        @Autowired
        HttpClientTracedInterceptor httpClientTracedInterceptor;
    
        @Autowired
        private AsyncAllService asyncAllService
        
        @GetMapping("/t1")
        public String te() throws ExecutionException, InterruptedException, IOException {
        
            log.trace("trace---test!!!!!");
            log.info("info---test!!!!!");
            log.warn("warn---test!!!!!");
            log.debug("debug---test!!!!!");
            log.error("error---test!!!!!");
            //有返回值的async任务
            Future<Long> longFuture = asyncAllService.testCount1();
            //无返回值的async任务
            asyncAllService.testAsync2();
            //有返回值的async任务,需要future执行后,最后统一get返回值
            Long l605 = longFuture.get();
            log.info("async task res:{}",l605);
    
            //测试使用apache httpclient 外发1个http请求
            String content = "test.dhrth.xxx.zzzdfg.derferf.sregvreg.regetg.esrtg34gf3";
            String url = "http://10.1.5.212:8008/api/getresult";
            Map<String, String> mapData = new HashMap<String, String>();
            mapData.put("type", "NER_RE");
            mapData.put("text", content);
            Map<String, Object> map = new HashMap<String, Object>();
            map.put("sid", "re");
            map.put("data", mapData);
            String reqStr = JSON.toJSONString(map);
            // 获取httpclient
            CloseableHttpClient httpclient = HttpClients.custom()
                    .addInterceptorFirst(httpClientTracedInterceptor)
                    .build();
            //创建post请求
            HttpPost httpPost = new HttpPost(url);
            RequestConfig requestConfig = RequestConfig.custom()
                    .setSocketTimeout(20*1000)
                    .setConnectionRequestTimeout(1000)
                    .setConnectTimeout(1000).build();
            httpPost.setConfig(requestConfig);
            StringEntity entity = new StringEntity(reqStr, ContentType.APPLICATION_JSON);
            httpPost.setEntity(entity);
            CloseableHttpResponse response = httpclient.execute(httpPost);
            // 得到响应信息
            int statusCode = response.getStatusLine().getStatusCode();
            log.info("http-res-statusCode:{}",statusCode);
    
            String respStr = EntityUtils.toString(response.getEntity(), "utf-8");
            log.info("http-resp:{}",respStr);
            return "thirdTestApi测试!";
        }
    }

测试控制台输出的日志效果

2023-06-05 15:45:54,228  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.s.l.ReqLogAspect [ReqLogAspect.java : 94] 请求URI:/kwb/third/t1
    2023-06-05 15:45:54,251  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.s.l.ReqLogAspect [ReqLogAspect.java : 107] 请求目标类:String cn.ath.knowwikibackend.rest.TestApi.te()
    2023-06-05 15:45:54,254  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.r.TestApi [TestApi.java : 60] info---test!!!!!
    2023-06-05 15:45:54,254  WARN [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.r.TestApi [TestApi.java : 61] warn---test!!!!!
    2023-06-05 15:45:54,255  ERROR [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.r.TestApi [TestApi.java : 63] error---test!!!!!
    2023-06-05 15:45:54,299  INFO [countTestTaskAsync-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.a.b.AsyncAllService [AsyncAllService.java : 35] now:2023-06-05 15:45:54
    2023-06-05 15:45:54,299  INFO [voidTestTaskAsync-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.a.b.AsyncAllService [AsyncAllService.java : 52] now:2023-06-05 15:45:54
    2023-06-05 15:45:54,300  INFO [countTestTaskAsync-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.a.b.AsyncAllService [AsyncAllService.java : 36] ---exec testCount1------------
    2023-06-05 15:45:54,300  INFO [voidTestTaskAsync-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.a.b.AsyncAllService [AsyncAllService.java : 53] ---exec testAsync2------------
    2023-06-05 15:45:54,300  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.r.TestApi [TestApi.java : 73] async task res:8
    2023-06-05 15:45:54,352  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.m.HttpClientTracedInterceptor [HttpClientTracedInterceptor.java : 36] req header item---->traceId: 8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4
    2023-06-05 15:45:55,429  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.r.TestApi [TestApi.java : 109] http-res-statusCode:200
    2023-06-05 15:45:55,431  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.r.TestApi [TestApi.java : 121] http-resp:{
        "status": "OK",
        "message": "提取成功",
        "result": {}
    }
    2023-06-05 15:45:55,432  INFO [http-nio-8080-exec-1] [8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4] c.a.k.s.l.ReqLogAspect [ReqLogAspect.java : 125] Around请求耗时:1227ms

从日志中可以看到，1次浏览器请求进到app后，从切面就开始mdc打点，之后的异步线程操作 和 外发http操作 的log日志中都显示出了本次浏览器请求对应的后台日志的打点traceId值为 8e5e137d-1bb0-49bc-b7da-c8b9f6568ef4