Spring Boot 中使用 MDC 追踪一次请求全过程

╰+攻爆jí腚メ 2022-11-21 11:17 609阅读 0赞

MDC 的全称是 `Mapped Diagnostic Context`，映射诊断上下文(MDC)。本质上是由日志框架维护的映射，其中应用程序代码提供键-值对，然后日志框架可以在日志消息中插入这些键-值对。MDC数据在过滤消息或触发某些操作方面也非常有用。管理开销。

SLF4J支持MDC，即映射的诊断上下文。如果底层日志框架提供MDC功能，那么SLF4J将委托给底层框架的MDC。注意，此时，只有log4j和logback提供MDC功能。如果底层框架不提供MDC，例如java.util。日志记录后，SLF4J仍将存储MDC数据，但其中的信息需要通过自定义用户代码检索。

为了惟一地标记每个请求，用户将上下文信息放入MDC中，MDC是映射诊断上下文的缩写。MDC类的比较重要的部分方法如下所示：

package org.slf4j;
    
    public class MDC {
      //Put a context value as identified by key
      //into the current thread's context map.
      public static void put(String key, String val);
    
      //Get the context identified by the key parameter.
      public static String get(String key);
    
      //Remove the context identified by the key parameter.
      public static void remove(String key);
    
      //Clear all entries in the MDC.
      public static void clear();
    }

MDC 类只包含静态方法。它允许开发人员在诊断上下文中放置信息，这些信息随后可由某些回签组件检索。MDC 按每个线程管理上下文信息。通常，在开始为新的客户机请求提供服务时，开发人员将插入相关的上下文信息，如客户机id、客户机的IP地址、请求参数等到 MDC 中。如果配置得当，登录组件将自动在每个日志条目中包含此信息。

请注意，由l`ogback-classic`实现的 MDC 假设以中等频率将值放置到 MDC 中。还请注意，子线程不会自动继承其父线程映射的诊断上下文的副本。

## 1、MDC 的基本使用 ##

下一个使用名为 SimpleMDC 的应用程序演示了这一基本原理。

package chapters.mdc;
    
    import org.slf4j.Logger;
    import org.slf4j.LoggerFactory;
    import org.slf4j.MDC;
    
    import ch.qos.logback.classic.PatternLayout;
    import ch.qos.logback.core.ConsoleAppender;
    
    public class SimpleMDC {
      static public void main(String[] args) throws Exception {
    
        // You can put values in the MDC at any time. Before anything else
        // we put the first name
        MDC.put("first", "Dorothy");
    
        [ SNIP ]
        
        Logger logger = LoggerFactory.getLogger(SimpleMDC.class);
        // We now put the last name
        MDC.put("last", "Parker");
    
        // The most beautiful two words in the English language according
        // to Dorothy Parker:
        logger.info("Check enclosed.");
        logger.debug("The most beautiful two words in English.");
    
        MDC.put("first", "Richard");
        MDC.put("last", "Nixon");
        logger.info("I am not a crook.");
        logger.info("Attributed to the former US president. 17 Nov 1973.");
      }
    
      [ SNIP ]
    
    }

main 方法首先将 Dorothy 值与 MDC 中的键关联起来。您可以在 MDC 中放置任意多的值/键关联。具有相同键的多次插入将覆盖较旧的值。然后代码继续配置logback。

为了简洁起见，我们省略了用配置文件simpleMDC.xml配置logback的代码。下面是该文件的相关部分。

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> 
      <layout>
        <Pattern>%X{first} %X{last} - %m%n</Pattern>
      </layout> 
    </appender>

注意在 PatternLayout 转换模式中使用了 %X 说明符。 %X 转换说明符被使用两次，一次用于第一个命名的键，一次用于最后一个命名的键。在获得与 SimpleMDC对应的日志程序之后。类中，代码将值Parker与名为last的键关联。然后，它使用不同的消息两次调用日志程序。代码最后将MDC设置为不同的值并发出几个日志记录请求。运行 SimpleMDC 会得到以下结果：

Dorothy Parker - Check enclosed.
    Dorothy Parker - The most beautiful two words in English.
    Richard Nixon - I am not a crook.
    Richard Nixon - Attributed to the former US president. 17 Nov 1973.

上面我们介绍了 MDC 的基本使用方法，下面我们就将这个技术使用到项目当中。

## 2、MDC 记录一次 HTTP 请求 ##

使用 Java 开发 Web 项目的时候我们就可以通过 MDC 跟踪 Java 应用程序一次请求完整的请求路径。我们的项目一般使用 Spring MVC，所以这里我就在请求 Controller 之前添加 MDC 值，然后在请求完成之后就把 MDC 清空。我想大家应该已经猜到了这里我会使用 Spring MVC 里面提供的拦截器 `HandlerInterceptor`，当然使用 Filter 也是可以的。

### 2.1 WebLogMdcHandlerInterceptor ###

调用 通过 `HandlerInterceptor#preHandle` 在调用 Controller 请求之前通过 UUID 生成唯一值。

public class WebLogMdcHandlerInterceptor extends HandlerInterceptorAdapter {
    
        @Override
        public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
            MDC.put("ctxLogId", UUID.randomUUID().toString());
            return true;
        }
    
        @Override
        public void afterCompletion(HttpServletRequest request, HttpServletResponse response,
                                    Object handler, Exception ex) throws Exception {
            MDC.clear();
        }
    
        @Override
        public void afterConcurrentHandlingStarted(HttpServletRequest request,
                                                   HttpServletResponse response, Object handler) throws Exception {
            preHandle(request, response, handler);
        }
    }

### 2.2 WebMvcConfig ###

它是一个配置类，通过实现 `WebMvcConfigurer` 与 注解 `@EnableWebMvc` 把我们创建的 `WebLogMdcHandlerInterceptor` 添加到 Spring 的容器当中。

@Configuration
    @EnableWebMvc
    public class WebMvcConfig implements WebMvcConfigurer {
    
    	@Override
    	public void addInterceptors(InterceptorRegistry registry) {
    		// MDC
    		WebLogMdcHandlerInterceptor mdcInterceptor = new WebLogMdcHandlerInterceptor();
    		registry.addInterceptor(mdcInterceptor);
    	}
    
    }

### 2.3 日志打印格式 ###

根据上面 MDC 中的基本使用规则，只需要通过 `%{ctxLogId}`，然后就可以把添加到日志跟踪号添加到日志打印当中了。

[%d{yyyy-MM-dd HH:mm:ss:SSS}] [%-5level] [%t] [%X{ctxLogId}] [%c(%L)] %m%n

打印效果如下：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI0MTA3MzM_size_16_color_FFFFFF_t_70_pic_center]  
这样你就可以通过请求的业务 ID 查询到一条或者多条日志信息，然后就可得到这个 MDC 值。通过这个 MDC 值你就可以把一次请求的整个日志的整个链路串联起来。这样排查问题就比较容易一点。

## 3、MDC 记录一次 Dubbo 请求 ##

因为 MDC 的请求是通过 Dubbo 调用，所以我们使用 `HandlerInterceptor` 并不会拦截它的请求。在这里我们可以使用 Dubbo 框架中的 `Filter` 拦截机制，把 MDC 添加到请求上下文当中。

### 3.1 ProviderMdcFilter ###

实现 Dubbo 提供的 Filter 机制，如果上游中传递过来了 MDC 值就使用上游传递过来的。否则就通过 UUID 自动生成一个添加到 MDC 当中。

public class ProviderMdcFilter implements Filter { 
    
        private Logger logger = LoggerFactory.getLogger(ProviderMdcFilter.class);
    
        @Override
        public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException { 
            String logId = invocation.getAttachment("ctxLogId",);
            if(StringUtils.isBlank(logId)){ 
                logId = UUID.randomUUID().toString();
                logger.warn("ProviderLogTraceIdFilter MDC log Id is null, UUID generate log id : {}", logId);
            }
            MDC.put("ctxLogId",, logId);
            try { 
                return invoker.invoke(invocation);
            } finally { 
                MDC.clear();
            }
        }
    }

### 3.2 配置生效 ###

要使得这个配置生效，首先需要把它添加到 dubbo 的容器里面。

*  最开始在 `resources` 目录下面创建 `META-INF.duboo` 目录
 *  然后在该目录下面创建文件名为 `org.apache.dubbo.rpc.Filter`
 *  最后在 Filter 文件中添加一个 `key = Filter 类全名` 这种格式的值

-- resources
      -- META-INF.dubbo
        -- org.apache.dubbo.rpc.Filter
    
    providerLoggerFilter=com.fintech.test.interceptor.ProviderMdcFilter

然后在 dubbo 配置文件当中添加以下代码就可以了。

dubbo.provider.filter=providerLoggerFilter

## 4、线程池打印 MDC ##

在我们项目中往往需要定时任务完成一些业务逻辑，而执行定时任务的时候往往是使用异步执行的。但是 `MDC` 是通过 `ThreadLocal` 执行的，所以普通方法我们行不通。下面我就分享一下我在项目当中是如何实现的。

在这里面我借鉴了一下 Spring 事务处理是通过模板方式来处理的，也就是 `TransactionTemplate`.

### 4.1 TaskLogIdTemplate ###

因为定时任务是查询出来多个结果，然后遍历结果传递到这个模板类当中。在这个模板类当中封装了定时任务异步执行的逻辑，并且每个需要执行的业务都可以自定义的传递上下文日志 ID 到模板类当中。

@Slf4j
    @Service("taskLogIdTemplate")
    public class TaskLogIdTemplate { 
    
        @Resource(name = "taskThreadPoolExecutor")
        private ThreadPoolTaskExecutor taskThreadPoolExecutor;
    
        public void execute(String ctxLogId, TaskLogIdCallback action){ 
            taskThreadPoolExecutor.execute(() -> { 
                MDC.put(CommonConstants.CTX_LOG_ID_MDC, ctxLogId);
                try { 
                    action.doInExecute();
                } catch (Exception e) { 
                    log.error("TaskLogIdTemplate#execute is error", e);
                } finally { 
                    MDC.clear();
                }
            });
        }
    
    }

### 4.2 TaskLogIdCallback ###

定时任务回调类，因为定时任务不需要返回值，所以就没有像事务处理一样定义返回值。

@FunctionalInterface
    public interface TaskLogIdCallback { 
    
        /** * 定时任务回调 * @return */
        void doInExecute();
    
    }

### 4.3 TaskServiceImpl ###

以下就是模拟订单完成的定时任务，这里我是通过订单号加上方法名来做为唯一的 MDC 值的。

public void finishOrder(){ 
    	List<Order> orders = queryObject(startTime, endTime);
    	if(CollectionUtils.isEmpty(orders)){ 
    	    return;
    	}
    	for (Order order : orders) { 
    	    String contextLogId = getContextLogId(order, methodName);
    	    taskLogIdTemplate.execute(contextLogId, () -> taskService.finishOrder(order));
    	}
    }
    
    private String getContextLogId(Order order, String methodName) { 
    	return order.getOrderNo + ":" + methodName;
    }

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI0MTA3MzM_size_16_color_FFFFFF_t_70_pic_center]: /images/20221120/071612866f1247abacdcbfe90bc190fa.png