需求
在访问量较大的分布式系统中,时时刻刻在打印着巨量的日志,当我们需要排查问题时,需要从巨量的日志信息中找到本次排查内容的日志是相对复杂的,那么,如何才能使日志看起来逻辑清晰呢?如果每一次请求都有一个全局唯一的id,当我们需要排查时,根据其他日志打印关键字定位到对应请求的全局唯一id,再根据id去搜索、筛选即可找到对应请求全流程的日志信息。接下来就是需要找一种方案,可以生成全局唯一id和在不同的线程中存储这个id。
解决方案
LogBack这个日志框架提供了MDC( Mapped Diagnostic Context,映射调试上下文 ) 这个功能,MDC可以理解为与线程绑定的数据存储器。数据可以被当前线程访问,当前线程的子线程会继承其父线程中MDC的内容。MDC 在 Spring Boot 中的作用是为日志事件提供上下文信息,并将其与特定的请求、线程或操作关联起来。通过使用 MDC,可以更好地理解和分析日志,并在多线程环境中确保日志的准确性和一致性。此外,MDC 还可以用于日志审计、故障排查和跟踪特定操作的执行路径。
代码
实现日志打印全局链路唯一id的功能,需要三个信息:
- 全局唯一ID生成器
- 请求拦截器
- 自定义线程池(可选)
- 日志配置
全局唯一ID生成器
生成器可选方案有:
- UUID,快速随机生成、极小概率重复
- Snowflake,有序递增
- 时间戳
雪花算法(Snowflake)更适用于需要自增的业务场景,如数据库主键、订单号、消息队列的消息ID等, 时间戳一般是微秒级别,极限情况下,一微秒内可能同时多个请求进来导致重复。系统时钟回拨时,UUID可能会重复,但是一般不会出现该情况,因此UUID这种方案的缺点可以接受,本案例使用UUID方案。
/*** 全局链路id生成工具类** @author Ltx* @version 1.0*/
public class RequestIdUtil {public RequestIdUtil() {}public static void setRequestId() {//往MDC中存入UUID唯一标识MDC.put(Constant.TRACE_ID, UUID.randomUUID().toString());}public static void setRequestId(String requestId) {MDC.put(Constant.TRACE_ID, requestId);}public static String getRequestId() {return MDC.get(Constant.TRACE_ID);}public static void clear() {//需要释放,避免OOMMDC.clear();}
}
/*** Author: liu_pc* Date: 2023/8/8* Description: 常量定义类* Version: 1.0*/
public class Constant {/*** 全局唯一链路id*/public final static String TRACE_ID = "traceId";
}
自定义全局唯一拦截器
Filter是Java Servlet 规范定义的一种过滤器接口,它的主要作用是在 Servlet 容器中对请求和响应进行拦截和处理,实现对请求和响应的预处理、后处理和转换等功能。通过实现 Filter 接口,开发人员可以自定义一些过滤器来实现各种功能,如身份验证、日志记录、字符编码转换、防止 XSS 攻击、防止 CSRF 攻击等。那么这里我们使用它对请求做MDC赋值处理。
@Component
public class RequestIdFilter implements Filter {@Overridepublic void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException{try {HttpServletRequest httpServletRequest = (HttpServletRequest) servletRequest;String requestId = httpServletRequest.getHeader("requestId");if (StringUtils.isBlank(requestId)) {RequestIdUtil.setRequestId();} else {RequestIdUtil.setRequestId(requestId);}// 继续将请求传递给下一个过滤器或目标资源(比如Controller)filterChain.doFilter(servletRequest, servletResponse);} finally {RequestIdUtil.clear();}}@Overridepublic void init(FilterConfig filterConfig) throws ServletException {Filter.super.init(filterConfig);}@Overridepublic void destroy() {Filter.super.destroy();}
}
/*** 测试MDC异步任务全局链路** @param param 请求参数* @return new String Info*/public String test(String param) {logger.info("测试MDC test 接口开始,请求参数:{}", param);String requestId = RequestIdUtil.getRequestId();logger.info("MDC RequestId :{}", requestId);return "hello";}
日志配置
输出到控制台:
<?xml version="1.0" encoding="UTF-8"?>
<configuration><!-- 配置输出到控制台(可选输出到文件) --><appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"><encoder><!-- 配置日志格式 --><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %mdc %msg%n</pattern></encoder></appender><!-- 配置根日志记录器 --><root level="INFO"><appender-ref ref="CONSOLE"/></root><!-- 配置MDC --><contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"><resetJUL>true</resetJUL></contextListener><!-- 配置MDC插件 --><conversionRule conversionWord="%mdc" converterClass="org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter"/>
</configuration>
输出到文件:
<configuration><!-- 配置输出到文件 --><appender name="FILE" class="ch.qos.logback.core.FileAppender"><!-- 指定日志文件路径和文件名 --><file>/Users/liu_pc/Documents/code/mdc_logback/logs/app.log</file><encoder><!-- 配置日志格式 --><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %mdc %msg%n</pattern></encoder></appender><!-- 配置根日志记录器 --><root level="INFO"><appender-ref ref="FILE"/></root><!-- 其他配置... -->
</configuration>
功能实现。
子线程获取traceId问题
使用多线程时,子线程打印日志拿不到traceId。如果在子线程中获取traceId,那么就相当于往各自线程中的MDC赋值了traceId,会导致子线程traceId不一致的问题。
public void wrongHelloAsync(String param) {logger.info("helloAsync 开始执行异步操作,请求参数:{}", param);List<Integer> simulateThreadList = new ArrayList<>(5);for (int i = 0; i <= 5; i++) {simulateThreadList.add(i);}for (Integer thread : simulateThreadList) {CompletableFuture.runAsync(() -> {//在子线程中赋值String requestId = RequestIdUtil.getRequestId();logger.info("子线程信息:{},traceId:{} ", thread, requestId);}, executor);}}
}
子线程获取traceId方案
使用子线程时,可以使用自定义线程池重写部分方法,在重写的方法中获取当前MDC数据副本,再将副本信息赋值给子线程的方案。
/*** Author: liu_pc* Date: 2023/8/7* Description: 自定义异步线程池配置* Version: 1.0*/
@Configuration
@EnableAsync
public class AsyncConfiguration implements AsyncConfigurer {private final Logger logger = LoggerFactory.getLogger(AsyncConfiguration.class);private final TaskExecutionProperties taskExecutionProperties;public AsyncConfiguration(TaskExecutionProperties taskExecutionProperties) {this.taskExecutionProperties = taskExecutionProperties;}@Override@Bean(name = "taskExecutor")public Executor initAsyncExecutor() {logger.debug("Creating Async Task Executor");ThreadPoolTaskExecutor executor = new MdcThreadPoolTaskExecutor();executor.setCorePoolSize(taskExecutionProperties.getPool().getCoreSize());executor.setMaxPoolSize(taskExecutionProperties.getPool().getMaxSize());executor.setQueueCapacity(taskExecutionProperties.getPool().getQueueCapacity());executor.setThreadNamePrefix(taskExecutionProperties.getThreadNamePrefix());return executor;}@Overridepublic AsyncUncaughtExceptionHandler getAsyncUncaughtExceptionHandler() {return new SimpleAsyncUncaughtExceptionHandler();}
}
/*** Author: liu_pc* Date: 2023/8/7* Description: 自定义携带MDC信息线程池* Version: 1.0*/
public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {@Overridepublic void execute(@Nonnull Runnable task) {Map<String, String> copyOfContextMap = MDC.getCopyOfContextMap();super.execute(() -> {if (Objects.nonNull(copyOfContextMap)) {String requestId = RequestIdUtil.getRequestId();if (StringUtils.isBlank(requestId)) {copyOfContextMap.put("traceId", UUID.randomUUID().toString());}//主线程MDC赋值子线程MDC.setContextMap(copyOfContextMap);} else {RequestIdUtil.setRequestId();}try {task.run();} finally {RequestIdUtil.clear();}});}
}
测试代码:
/*** 测试MDC异步任务全局链路** @param param 请求参数* @return new String Info*/public String test(String param) {logger.info("测试MDC test 接口开始,请求参数:{}", param);String requestId = RequestIdUtil.getRequestId();logger.info("MDC RequestId :{}", requestId);helloAsyncService.helloAsync(param, requestId);return "hello";}
/*** 使用异步数据测试打印日志** @param param 请求参数* @param requestId 全局唯一id*/@Async("taskExecutor")public void helloAsync(String param, String requestId) {logger.info("helloAsync 开始执行异步操作,请求参数:{}", param);List<Integer> simulateThreadList = new ArrayList<>(5);for (int i = 0; i <= 5; i++) {simulateThreadList.add(i);}for (Integer thread : simulateThreadList) {CompletableFuture.runAsync(() -> {//在子线程中赋值RequestIdUtil.setRequestId(requestId);logger.info("子线程信息:{},traceId:{} ", thread, requestId);}, executor);}}