Java Web中日志跟蹤的簡單實現
一、前言
在編碼過程中，常常需要寫打印日志語句，我們期望的是同一個業務的日志都在一塊，在出問題的時候好根據日志來排查問題。而現實是在應用運行中，日志的輸出常常來自不同線程，甚至是在不同微服務中，各種日志記錄往往彼此穿插，很難串起來。所以往往在日志中手動增加一些關鍵字，來對接口的調用鏈路來進行跟蹤。但這種手動增加關鍵字或唯一標識的做法在微服務場景下，很難在上下游應用的開發人員的編碼風格形成統一的規范，并且手動編寫也很難稱得上優雅。
二、MDC介紹
MDC（Mapped Diagnostic Context，映射調試上下文）是 log4j 、logback及log4j2 提供的一種方便在多線程條件下記錄日志的功能。MDC 可以看成是一個與當前線程綁定的哈希表，MDC 中包含的內容可以被同一線程中執行的代碼所訪問。
MDC中的鍵值對是可以直接被日志框架所使用（即“打印”）的，只需要配置相應日志pattern。例如pattern如下：
%d{HH:mm:ss.SSS} [%thread] [%X{TraceId}] %-5level %logger{50} - %msg%n
代碼如下：
public class MDCTest {
private static final Logger log = LoggerFactory.getLogger(MDCTest.class);
@Test
void test() {
MDC.put("TraceId", "123456789");
log.info("hello {}", "world");
}
}
此時控制臺將輸出：
21:16:04.342 [main] [123456789] INFO com.nk.MDCTest - hello world
三、實現方案
1、基本思路
修改日志pattern，并在業務開始的時候將trace id放入到MDC，在業務結束時去除MDC的trace id。這樣的好處便是代碼簡潔，不需要手動寫trace id，日志風格也能保持統一。
業務開始的時機一般是應用收到HTTP請求，所以可以用Filter或SpringMVC的Interceptor來對MDC中trace id進行初始化和清除。在Dubbo調用的時候也可以通過類似功能的Filter來對MDC中trace id進行操作，從而達到trace id傳遞的作用。
2、實現（以SpringBoot為例）
2.1 修改log pattern
在SpringBoot中，直接修改application.properties即可：
logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{TraceId}] %-5level %logger{50} - %msg%n
重點在于%X{TraceId}，其中TraceId需要作為key出現在MDC里。
2.1.1 業務開始
TraceId工具類，封裝MDC關于trace id的基礎操作：
public final class TraceIdUtil {
private static final String TRACE_ID_KEY = "TraceId";
private TraceIdUtil() {
}
public static void putIfAbsent() {
if (StrUtil.isBlank(get())) {
put(UUID.randomUUID().toString());
}
}
public static void remove() {
if (get() != null) {
MDC.remove(TRACE_ID_KEY);
}
}
public static String get() {
return MDC.get(TRACE_ID_KEY);
}
public static void put(String traceId) {
MDC.put(TRACE_ID_KEY, traceId);
}
}
Filter方式和Interceptor二選其一既可，其基本思想是一樣的。
Filter方式
@Component
public class LogFilter implements Filter {
@Override
public void doFilter(ServletRequest servletRequest,
ServletResponse servletResponse,
FilterChain filterChain) throws IOException, ServletException {
TraceIdUtil.putIfAbsent();//生成trace id放入MDC中
try {
filterChain.doFilter(servletRequest, servletResponse);
} finally {
TraceIdUtil.remove();//移除MDC中的trace id
}
}
}
Interceptor
@Configuration
public class LogInterceptor implements WebMvcConfigurer {
@Override
public void addInterceptors(InterceptorRegistry registry) {
registry.addInterceptor(new AsyncHandlerInterceptor() {
@Override
public boolean preHandle(HttpServletRequest request,
HttpServletResponse response,
Object handler) throws Exception {
TraceIdUtil.putIfAbsent();//生成trace id放入MDC中
return AsyncHandlerInterceptor.super.preHandle(request, response, handler);
}
@Override
public void afterCompletion(HttpServletRequest request,
HttpServletResponse response,
Object handler, Exception ex) throws Exception {
TraceIdUtil.remove();//移除MDC中的trace id
AsyncHandlerInterceptor.super.afterCompletion(request, response, handler, ex);
}
});
WebMvcConfigurer.super.addInterceptors(registry);
}
}
2.1.2 業務中使用
正常使用logger，無需關心trace id。例如：
@RestController
@RequestMapping("/api/user")
@Slf4j
public class UserController {
@Autowired
private UserService userService;
@GetMapping("/{userId}")
public UserDto queryUser(@PathVariable Long userId) {
log.info("query user by id:{}", userId);
UserDto user = userService.query(userId);
log.info("query user result:{}", user);
return user;
}
}
請求該接口將輸出如下的日志樣式：
2022-04-05 09:40:17.638 [http-nio-8080-exec-1] [a02b13d81c224e49956afd4efbb85ca8] INFO com.nk.webapp.controller.UserController - ready to query user by id:1
2022-04-05 09:40:17.670 [http-nio-8080-exec-1] [a02b13d81c224e49956afd4efbb85ca8] INFO com.nk.webapp.controller.UserController - query result:UserDto(userId=1, username=zhang3, age=23, email=abc@example.com)
四、總結
日志鏈路的跟蹤核心是使用MDC作為trace id載體，在業務開始階段一般通過攔截器就生成trace id并放入到MDC中，并根據MDC的相關特性將trace id投射到日志文本中，從而實現在同一個業務調用鏈路中的日志具有唯一標識。
