"If debugging is the process of removing software bugs, then programming must be the process of putting them in." - Edsger Dijkstra “如果調試是消除軟體Bug的過程，那 ...
"If debugging is the process of removing software bugs, then programming must be the process of putting them in." - Edsger Dijkstra
“如果調試是消除軟體Bug的過程，那麼編程就是產出Bug的過程。” —— 艾茲格·迪傑斯特拉
0x00 大綱
目錄0x01 前言
當你的應用程式同時處理多個用戶的請求時，你會看到日誌文件或者控制臺中的輸出通常都是交錯的，而非線性連續的。尤其是在分散式系統中，一個用戶請求可能包含了若幹次的服務節點調用，它的日誌也因此變得碎片化，如果缺乏一個用於歸類和關聯的標識，就會導致這筆交易難以被跟蹤和追查。
MDC(Mapped Diagnostic Context)是一種用於區分來自不同來源日誌的工具。它的本質是一個由日誌框架維護的Map存儲結構，應用程式可以向其中寫入鍵值對，並被日誌框架訪問。我們常用的日誌門面SLF4J就對MDC的實現進行了抽象，由日誌框架提供真正的實現。在SLF4J的文檔中寫道：
This class hides and serves as a substitute for the underlying logging system's MDC implementation.
If the underlying logging system offers MDC functionality, then SLF4J's MDC, i.e. this class, will delegate to the underlying system's MDC. Note that at this time, only two logging systems, namely log4j and logback, offer MDC functionality. For java.util.logging which does not support MDC, BasicMDCAdapter will be used. For other systems, i.e. slf4j-simple and slf4j-nop, NOPMDCAdapter will be used.
Thus, as a SLF4J user, you can take advantage of MDC in the presence of log4j, logback, or java.util.logging, but without forcing these systems as dependencies upon your users.
目前為止只有logback和log4j(log4j2)提供了較為完備的實現，其餘日誌框架下會使用SLF4J內部實現的BasicMDCAdapter或者NOPMDCAdapter.
0x02 應用場景
CLI 程式
以logback為例，我們創建一個簡單的logback.xml配置文件：
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false">
<property name="log.pattern" value="[%thread][%level][%logger{42}][%X{traceId:--}] %msg%n%ex"/>
<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>${log.pattern}</pattern>
</layout>
</appender>
<root level="INFO">
<appender-ref ref="stdout"/>
</root>
</configuration>
一個簡單的類用於測試，我們用一個迴圈來模擬用戶兩個獨立的請求：
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import java.util.UUID;
public class Main {
private static final Logger LOGGER = LoggerFactory.getLogger(Main.class);
public static void main(String[] args) {
for (int i = 0; i < 2; i++) {
try {
LOGGER.info("Empty MDC Before Putting Data.");
MDC.put("traceId", UUID.randomUUID().toString());
LOGGER.info("Hello MDC.");
LOGGER.info("GoodBye MDC.");
throw new RuntimeException("Test Exception");
} catch (RuntimeException e) {
LOGGER.error("Test MDC", e);
} finally {
MDC.clear();
LOGGER.info("Empty MDC After Clearing Data.");
}
}
}
}
運行之後，我們會得到類似這樣的日誌輸出：
[main][INFO][com.example.Main][-] Empty MDC Before Putting Data.
[main][INFO][com.example.Main][9ed7cc12-3880-4a38-94d4-b7ba96f37234] Hello MDC.
[main][INFO][com.example.Main][9ed7cc12-3880-4a38-94d4-b7ba96f37234] GoodBye MDC.
[main][ERROR][com.example.Main][9ed7cc12-3880-4a38-94d4-b7ba96f37234] Test MDC
java.lang.RuntimeException: Test Exception
at com.example.Main.main(Main.java:19)
[main][INFO][com.example.Main][-] Empty MDC After Clearing Data.
[main][INFO][com.example.Main][-] Empty MDC Before Putting Data.
[main][INFO][com.example.Main][ab94804a-4f9a-4474-ba23-98542884d0ea] Hello MDC.
[main][INFO][com.example.Main][ab94804a-4f9a-4474-ba23-98542884d0ea] GoodBye MDC.
[main][ERROR][com.example.Main][ab94804a-4f9a-4474-ba23-98542884d0ea] Test MDC
java.lang.RuntimeException: Test Exception
at com.example.Main.main(Main.java:19)
[main][INFO][com.example.Main][-] Empty MDC After Clearing Data.
可以看到，兩次請求的traceId是不一樣的，這樣就能在日誌中將它們區分和識別開來。通常來說，最好在請求完成後對MDC中的數據進行清理，尤其是使用了線程池的情況，由於線程是復用的，除非對原來的鍵值進行了覆蓋，否則它將保留上一次的值。
Web 應用（服務端）
在CLI程式中，我們可以用上面的寫法來設置traceId，當時對於 Web 應用，由於Controller入口眾多，不可能每個控制器都這樣子寫，可以使用攔截器實現公共邏輯，避免對Controller的方法造成污染。先增加一個簡單的Controller，它有兩個請求處理方法，一個同步，一個非同步：
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import java.util.Map;
import java.util.concurrent.Callable;
@RestController
public class MDCController {
private static final Logger LOGGER = LoggerFactory.getLogger(MDCController.class);
@Configuration
public class WebMvcConfig implements WebMvcConfigurer {
@Override
public void addInterceptors(InterceptorRegistry registry) {
registry.addInterceptor(new LogInterceptor()).addPathPatterns("/**");
}
}
@GetMapping("/syncMDC")
public String mdcSync() {
LOGGER.info("sync MDC test.");
return "syncMDC";
}
@GetMapping("/asyncMDC")
public Callable<String> mdcAsync() {
LOGGER.info("async MDC test.");
Map<String, String> mdcMap = MDC.getCopyOfContextMap();
return () -> {
try {
MDC.setContextMap(mdcMap);
LOGGER.info("非同步業務邏輯處理");
return "asyncMDC";
} finally {
MDC.clear();
}
};
}
}
然後是關鍵的MDC攔截器：
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.web.servlet.AsyncHandlerInterceptor;
import javax.servlet.DispatcherType;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;
/**
* 日誌增強攔截器，給輸出日誌加上鏈路跟蹤號
*
* @author YanFaBu
**/
public class LogInterceptor implements AsyncHandlerInterceptor {
private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
if (request.getDispatcherType() != DispatcherType.REQUEST) {
// 非 DispatcherType.REQUEST 分發類型，嘗試從 Attribute 獲取 LOG_TRACE_ID
MDC.put("traceId", (String) request.getAttribute("traceId"));
LOGGER.info("preHandle Non DispatcherType.REQUEST type with DispatcherType {}", request.getDispatcherType());
return true;
}
// 如果本次調用來自上游服務，那麼嘗試從請求頭獲取上游傳遞的 traceId
String traceId = request.getHeader("traceId");
if (traceId == null) {
// 本服務節點是起始服務節點，設置 traceId
traceId = UUID.randomUUID().toString();
}
MDC.put("traceId", traceId);
// 非同步處理會在內部進行 Request 轉發，通過 Attribute 攜帶 traceId
request.setAttribute("traceId", traceId);
LOGGER.info("preHandle DispatcherType.REQUEST type with DispatcherType {}", request.getDispatcherType());
return true;
}
@Override
public void afterConcurrentHandlingStarted(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
// 清理 MDC
LOGGER.info("afterConcurrentHandlingStarted Clearing MDC.");
MDC.clear();
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception exception) {
// 清理 MDC
LOGGER.info("afterCompletion Clearing MDC with DispatcherType {}", request.getDispatcherType());
MDC.clear();
}
}
分別訪問這兩個Controller方法，應當看到類似這樣的日誌輸出：
[http-nio-8080-exec-7][INFO][com.example.LogInterceptor][e828f77b-9c0d-42c5-83db-15f19153bf19] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-7][INFO][com.example.MDCController][e828f77b-9c0d-42c5-83db-15f19153bf19] sync MDC test.
[http-nio-8080-exec-7][INFO][com.example.LogInterceptor][e828f77b-9c0d-42c5-83db-15f19153bf19] afterCompletion Clearing MDC with DispatcherType REQUEST
[http-nio-8080-exec-8][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-8][INFO][com.example.MDCController][7dc0878c-c014-44de-97d4-92108873a030] async MDC test.
[http-nio-8080-exec-8][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] afterConcurrentHandlingStarted Clearing MDC.
[task-3][INFO][com.example.MDCController][7dc0878c-c014-44de-97d4-92108873a030] 非同步業務邏輯處理
[http-nio-8080-exec-9][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] preHandle Non DispatcherType.REQUEST type with DispatcherType ASYNC
[http-nio-8080-exec-9][INFO][com.example.LogInterceptor][7dc0878c-c014-44de-97d4-92108873a030] afterCompletion Clearing MDC with DispatcherType ASYNC
註意到非同步請求處理中的線程號的變化，請求受理-業務處理-請求應答歷經了3個不同的線程，凡是跨線程的處理邏輯，必然需要對MDC的傳遞進行處理，否則鏈路跟蹤會丟失。網上看到過很多例子，都忽略了對DispatcherType的處理，這樣就會導致非同步請求中，有一部分日誌會失去追蹤，導致最終排查問題時鏈路不完整。通過Attribute傳遞不是唯一的方式，也可以藉助其他上下文來傳遞。
Web 應用（客戶端）
OkHttp 同步請求
import okhttp3.OkHttpClient;
import okhttp3.Request;
import okhttp3.Response;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import java.io.IOException;
import java.util.Objects;
import java.util.UUID;
public class Client {
private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);
public static void main(String[] args) throws IOException {
okHttpSync();
}
public static void okHttpSync() throws IOException {
try {
String traceId = UUID.randomUUID().toString();
MDC.put("traceId", traceId);
LOGGER.info("okHttpSync request syncMDC");
OkHttpClient client = new OkHttpClient().newBuilder()
.build();
Request request = new Request.Builder()
.url("http://localhost:8080/syncMDC")
.method("GET", null)
.addHeader("traceId", traceId)
.build();
try (Response response = client.newCall(request).execute()) {
LOGGER.info("okHttpSync response：{}", Objects.requireNonNull(response.body()).string());
}
} finally {
MDC.clear();
}
}
}
OkHttp 非同步請求
import okhttp3.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import java.io.IOException;
import java.util.Map;
import java.util.Objects;
import java.util.UUID;
public class Client {
private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);
public static void main(String[] args) {
okHttpAsync();
}
public static void okHttpAsync() {
try {
String traceId = UUID.randomUUID().toString();
MDC.put("traceId", traceId);
LOGGER.info("okHttpAsync request syncMDC");
OkHttpClient client = new OkHttpClient().newBuilder()
.build();
Request request = new Request.Builder()
.url("http://localhost:8080/syncMDC")
.method("GET", null)
.addHeader("traceId", traceId)
.build();
Map<String, String> mdcMap = MDC.getCopyOfContextMap();
client.newCall(request).enqueue(new Callback() {
@Override
public void onFailure(Call call, IOException e) {
try {
MDC.setContextMap(mdcMap);
LOGGER.error("okHttpAsync error", e);
} finally {
MDC.clear();
}
}
@Override
public void onResponse(Call call, Response response) throws IOException {
try {
MDC.setContextMap(mdcMap);
LOGGER.info("okHttpAsync response：{}", Objects.requireNonNull(response.body()).string());
} finally {
MDC.clear();
}
}
});
} finally {
MDC.clear();
}
}
}
順利的話，在客戶端應該會得到類似下麵的日誌輸出（註意線程名稱的變化）：
[main][INFO][com.example.Client][53924455-0fcd-442b-a5aa-aaa33005d299] okHttpSync request syncMDC
[main][INFO][com.example.Client][53924455-0fcd-442b-a5aa-aaa33005d299] okHttpSync response：syncMDC
[main][INFO][com.example.Client][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] okHttpAsync request syncMDC
[OkHttp http://localhost:8080/...][INFO][com.example.Client][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] okHttpAsync response：syncMDC
在服務端對應的日誌如下，可以看到traceId是一致的（如果不一致或者沒有看到traceId，應該檢查下上一章提到的攔截器是否有被正確實現）：
[http-nio-8080-exec-2][INFO][com.example.LogInterceptor][53924455-0fcd-442b-a5aa-aaa33005d299] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-2][INFO][com.example.MDCController][53924455-0fcd-442b-a5aa-aaa33005d299] sync MDC test.
[http-nio-8080-exec-2][INFO][com.example.LogInterceptor][53924455-0fcd-442b-a5aa-aaa33005d299] afterCompletion Clearing MDC with DispatcherType REQUEST
[http-nio-8080-exec-3][INFO][com.example.LogInterceptor][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-3][INFO][com.example.MDCController][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] sync MDC test.
[http-nio-8080-exec-3][INFO][com.example.LogInterceptor][5cb52293-c8ac-4bc5-87fc-dbeb1e727eba] afterCompletion Clearing MDC with DispatcherType REQUEST
處理思路都是通過HTTP Header攜帶traceId到下游服務，讓下游服務可以跟蹤來源。註意非同步請求時，請求處理和應答處理回調線程不在同一個線程，需要對MDC的傳遞進行處理，否則鏈路跟蹤會丟失。其他的客戶端，如HttpClient、Unirest等 HTTP 請求庫原理與之相似，這裡就不一一列舉了。
Spring WebClient
與OkHttp非同步調用類似，註意要在Mono或者Flux的subscribe方法中傳遞MDC上下文。其實WebClient中有Context傳遞的概念，但是這塊資料比較少，非同步非阻塞的代碼又看得頭痛，暫時不想去研究了。下麵的代碼出於演示目的使用，請勿直接使用：
import okhttp3.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.web.reactive.function.client.WebClient;
import java.io.IOException;
import java.util.Map;
import java.util.Objects;
import java.util.UUID;
import java.util.concurrent.CountDownLatch;
public class Client {
private static final Logger LOGGER = LoggerFactory.getLogger(LogInterceptor.class);
public static void main(String[] args) throws InterruptedException {
webClient();
}
public static void webClient() throws InterruptedException {
String traceId = UUID.randomUUID().toString();
MDC.put("traceId", traceId);
LOGGER.info("webClient request syncMDC");
WebClient client = WebClient.create("http://localhost:8080/syncMDC");
Map<String, String> mdcMap = MDC.getCopyOfContextMap();
CountDownLatch latch = new CountDownLatch(1);
client.get()
.uri("/")
.retrieve()
.bodyToMono(String.class)
.subscribe(result -> {
try {
MDC.setContextMap(mdcMap);
LOGGER.info("webClient response：{}", result);
} finally {
MDC.clear();
latch.countDown();
}
}, throwable -> {
try {
MDC.setContextMap(mdcMap);
LOGGER.error("webClient error", throwable);
} finally {
MDC.clear();
}
});
latch.await();
}
}
輸出日誌如下，註意線程的變化：
[main][INFO][com.example.Client][8c984fa8-e3cd-4914-875e-ba333d31c7a9] webClient request syncMDC
[reactor-http-nio-2][INFO][com.example.Client][8c984fa8-e3cd-4914-875e-ba333d31c7a9] webClient response：syncMDC
Dubbo 服務
與 HTTP 調用類似，基於Dubbo的 RPC 調用也是可以跟蹤的，利用Dubbo的Filter和SPI註冊機制，我們可以增加自己的過濾器實現日誌鏈路跟蹤：
import org.apache.dubbo.common.extension.Activate;
import org.apache.dubbo.rpc.*;
import org.slf4j.MDC;
import java.util.UUID;
/**
* 服務鏈路跟蹤過濾器
*/
@Activate
public class RpcTraceFilter implements Filter {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
RpcContext context = RpcContext.getContext();
boolean shouldRemove = false;
if (context.isProviderSide()) {
// 獲取消費端設置的參數
String traceId = context.getAttachment("traceId");
if (traceId == null || traceId.isEmpty()) {
traceId = MDC.get("traceId");
if (traceId == null || traceId.isEmpty()) {
traceId = UUID.randomUUID().toString();
shouldRemove = true;
}
}
// 設置 traceId
MDC.put("traceId", traceId);
// 繼續設置下游參數，供在提供方裡面作為消費端時，其他服務提供方使用這些參數
context.setAttachment("traceId", traceId);
} else if (context.isConsumerSide()) {
// 如果連續調用多個服務，則會使用同個線程里之前設置的traceId
String traceId = MDC.get("traceId");
if (traceId == null || traceId.isEmpty()) {
traceId = UUID.randomUUID().toString();
// 設置 traceId
MDC.put("traceId", traceId);
shouldRemove = true;
}
// 設置傳遞到提供端的參數
context.setAttachment("traceId", traceId);
}
try {
return invoker.invoke(invocation);
} finally {
// 調用完成後移除MDC屬性
if (shouldRemove) {
MDC.clear();
}
}
}
}
在需要用到的服務模塊的resource/META-INF/dubbo/org.apache.dubbo.rpc.Filter文件中註冊過濾器（註意路徑和名稱不能錯）：
rpcTraceFilter=com.example.RpcTraceFilter
SpringBoot的application.properties中增加配置（為了簡單驗證，這裡沒有使用註冊中心。如果你想更嚴謹地測試，建議在本地啟動兩個獨立的工程，並使用ZooKeeper進行服務註冊）：
dubbo.application.name=MDCExample
dubbo.scan.base-packages=com.example
dubbo.registry.address=N/A
# dubbo filter
dubbo.consumer.filter=rpcTraceFilter
dubbo.provider.filter=rpcTraceFilter
增加一個簡單的Dubbo服務：
import org.apache.dubbo.config.annotation.DubboService;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@DubboService
public class RpcService implements IRpcService {
private static final Logger LOGGER = LoggerFactory.getLogger(RpcService.class);
public String mdcRpc() {
LOGGER.info("Calling RPC service.");
return "mdcRpc";
}
}
在Controller中增加一個方法，進行驗證：
import org.apache.dubbo.config.annotation.DubboReference;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import java.util.Map;
import java.util.concurrent.Callable;
@RestController
public class MDCController {
// ......（省略前面的代碼）
@DubboReference
private IRpcService rpcService;
@GetMapping("/mdcRpc")
public String mdcRpc() {
LOGGER.info("rpc MDC test.");
return rpcService.mdcRpc();
}
}
訪問Controller方法，應該能得到類似下麵的輸出：
[http-nio-8080-exec-1][INFO][com.example.LogInterceptor][f003f750-2044-41ae-a041-8a76eb0c415b] preHandle DispatcherType.REQUEST type with DispatcherType REQUEST
[http-nio-8080-exec-1][INFO][com.example.MDCController][f003f750-2044-41ae-a041-8a76eb0c415b] rpc MDC test.
[http-nio-8080-exec-1][INFO][com.example.RpcService][f003f750-2044-41ae-a041-8a76eb0c415b] Calling RPC service.
[http-nio-8080-exec-1][INFO][com.example.LogInterceptor][f003f750-2044-41ae-a041-8a76eb0c415b] afterCompletion Clearing MDC with DispatcherType REQUEST
線程池
前面提到過跨線程調用時，需要自己處理MDC上下文的傳遞，如果是單個線程，可以手工進行處理，但如果是線程池，似乎就不能這麼幹了。線程池種類繁多，處理方式也有細微差別，這裡不可能全部列舉，以Spring項目中常用的 ThreadPoolTaskExecutor為例，我們可以利用它提供的setTaskDecorator方法對任務進行裝飾：
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.context.annotation.Bean;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import java.util.Map;
import java.util.UUID;
public class MDCExecutor {
private static final Logger LOGGER = LoggerFactory.getLogger(MDCExecutor.class);
public static void main(String[] args) {
MDC.put("traceId", UUID.randomUUID().toString());
ThreadPoolTaskExecutor executor = asyncTaskExecutor();
executor.initialize();
executor.submit(() -> LOGGER.info("MDC Executor"));
executor.shutdown();
}
@Bean
public static ThreadPoolTaskExecutor asyncTaskExecutor() {
ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
executor.setTaskDecorator(task -> {
Map<String, String> mdcMap = MDC.getCopyOfContextMap();
return () -> {
try {
if (mdcMap != null) {
MDC.setContextMap(mdcMap);
}
task.run();
} finally {
MDC.clear();
}
};
});
return executor;
}
}
對於其他線程池，通用的思路是覆寫其submit或者execute方法來實現MDC傳遞，比如我們下麵提到的定時任務調度線程池。
定時任務
除了Controller和 RPC 介面發起的調用，最常見的就是定時任務了。如果是定時任務作為業務發起源，可以在任務調度的時候對MDC進行處理。這塊處理比較複雜，暫時沒有找到比較優雅的切入點：
增加一個實現RunnableScheduledFuture介面的DecoratedFuture類：
import org.slf4j.MDC;
import java.util.Map;
import java.util.Optional;
import java.util.UUID;
import java.util.concurrent.*;
class DecoratedFuture<V> implements RunnableScheduledFuture<V> {
Runnable runnable;
Callable<V> callable;
final RunnableScheduledFuture<V> task;
public DecoratedFuture(Runnable r, RunnableScheduledFuture<V> task) {
this.task = task;
runnable = r;
}
public DecoratedFuture(Callable<V> c, RunnableScheduledFuture<V> task) {
this.task = task;
callable = c;
}
@Override
public boolean isPeriodic() {
return task.isPeriodic();
}
@Override
public void run() {
try {
Map<String, String> mdcMap = MDC.getCopyOfContextMap();
Optional.ofNullable(mdcMap).ifPresent(MDC::setContextMap);
String traceId = MDC.get("traceId");
if (traceId == null || traceId.isEmpty()) {
traceId = UUID.randomUUID().toString();
}
MDC.put("traceId", traceId);
task.run();
} finally {
MDC.clear();
}
}
@Override
public boolean cancel(boolean mayInterruptIfRunning) {
return task.cancel(mayInterruptIfRunning);
}
@Override
public boolean isCancelled() {
return task.isCancelled();
}
@Override
public boolean isDone() {
return task.isDone();
}
@Override
public V get() throws InterruptedException, ExecutionException {
return task.get();
}
@Override
public V get(long timeout, TimeUnit unit) throws InterruptedException, ExecutionException, TimeoutException {
return task.get(timeout, unit);
}
@Override
public long getDelay(TimeUnit unit) {
return task.getDelay(unit);
}
@Override
public int compareTo(Delayed o) {
return task.compareTo(o);
}
@Override
public int hashCode() {
return task.hashCode();
}
@Override
public boolean equals(Object o) {
if (this == o) {
return true;
}
if (o == null || getClass() != o.getClass()) {
return false;
}
DecoratedFuture<?> that = (DecoratedFuture<?>) o;
return this.task.equals(that.task);
}
public Runnable getRunnable() {
return runnable;
}
public RunnableScheduledFuture<V> getTask() {
return task;
}
public Callable<V> getCallable() {
return callable;
}
}
增加一個實現ThreadPoolTaskScheduler介面的DecoratedThreadPoolTaskScheduler類：
import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler;
import java.time.Duration;
import java.time.Instant;
import java.util.Map;
import java.util.Optional;
import java.util.concurrent.RejectedExecutionHandler;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.ScheduledFuture;
import java.util.concurrent.ThreadFactory;
class DecoratedThreadPoolTaskScheduler extends ThreadPoolTaskScheduler {
private static final long serialVersionUID = 1L;
static Runnable withTraceId(Runnable task) {
Map<String,String> mdcMap = MDC.getCopyOfContextMap();
return ()-> {
try {
Optional.ofNullable(mdcMap).ifPresent(MDC::setContextMap);
task.run();
} finally {
MDC.clear();
}
};
}
@Override
protected ScheduledExecutorService createExecutor(int poolSize, ThreadFactory threadFactory, RejectedExecutionHandler rejectedExecutionHandler) {
return new DecoratedScheduledThreadPoolExecutor(poolSize, threadFactory, rejectedExecutionHandler);
}
@Override
public ScheduledFuture<?> schedule(Runnable task, Instant startTime) {
return super.schedule(withTraceId(task), startTime);
}
@Override
public ScheduledFuture<?> scheduleAtFixedRate(Runnable task, Instant startTime, Duration period) {
return super.scheduleAtFixedRate(withTraceId(task), startTime, period);
}
@Override
public ScheduledFuture<?> scheduleAtFixedRate(Runnable task, Duration period) {
return super.scheduleAtFixedRate(withTraceId(task), period);
}
@Override
public ScheduledFuture<?> scheduleWithFixedDelay(Runnable task, Instant startTime, Duration delay) {
return super.scheduleWithFixedDelay(withTraceId(task), startTime, delay);
}
@Override
public ScheduledFuture<?> scheduleWithFixedDelay(Runnable task, Duration delay) {
return super.scheduleWithFixedDelay(withTraceId(task), delay);
}
}
增加一個繼承ScheduledThreadPoolExecutor類的DecoratedScheduledThreadPoolExecutor類，覆寫它的兩個decorateTask方法：
import java.util.concurrent.*;
class DecoratedScheduledThreadPoolExecutor extends ScheduledThreadPoolExecutor {
public DecoratedScheduledThreadPoolExecutor(int poolSize, ThreadFactory threadFactory, RejectedExecutionHandler rejectedExecutionHandler) {
super(poolSize, threadFactory, rejectedExecutionHandler);
}
@Override
protected <V> RunnableScheduledFuture<V> decorateTask(Runnable runnable, RunnableScheduledFuture<V> task) {
return new DecoratedFuture<>(runnable, task);
}
@Override
protected <V> RunnableScheduledFuture<V> decorateTask(Callable<V> callable, RunnableScheduledFuture<V> task) {
return new DecoratedFuture<>(callable, task);
}
}
在定時任務Configuration中，創建DecoratedThreadPoolTaskScheduler作為調度線程池：
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.EnableAsync;
import org.springframework.scheduling.annotation.EnableScheduling;
import org.springframework.scheduling.annotation.SchedulingConfigurer;
import org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler;
import org.springframework.scheduling.config.ScheduledTaskRegistrar;
/**
* 定時調度配置
*/
@Configuration
@EnableAsync
@EnableScheduling
public class SchedulingConfiguration implements SchedulingConfigurer {
public static final String TASK_SCHEDULER = "taskScheduler";
@Override
public void configureTasks(ScheduledTaskRegistrar taskRegistrar) {
taskRegistrar.setTaskScheduler(taskScheduler());
}
@Bean(TASK_SCHEDULER)
public ThreadPoolTaskScheduler taskScheduler() {
return new DecoratedThreadPoolTaskScheduler();
}
}
添加一個簡單定時任務：
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.scheduling.annotation.Scheduled;
@SpringBootApplication
public class App {
private static final Logger LOGGER = LoggerFactory.getLogger(App.class);
public static void main(String[] args) {
SpringApplication.run(App.class, args);
}
@Scheduled(fixedDelay = 1500)
public void cronTaskConfigRefresh() {
LOGGER.info("MDC task scheduler.");
}
}
可以看到類似下麵的輸出，說明就成功了：
[taskScheduler-1][INFO][com.example.App][0959d1a6-4680-4a95-a29b-b62694f0d348] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][8f034b1e-db40-44cb-9fc2-986eb8f0da6d] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][02428e88-53f8-4151-aba0-86e069c96462] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][fcd5d925-95e0-4e28-aa68-39e765668dde] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][b8ed50c6-0d6d-40c0-b170-976717fe7d22] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][9d173a26-41d4-43dc-beae-731a9f267288] MDC task scheduler.
[taskScheduler-1][INFO][com.example.App][0257c93a-9bec-40b7-9447-5a938bd2ce5f] MDC task scheduler.
0x03 小結
在實際項目中，通過靈活組合上面的若幹種手段，就可以實現輕量化的日誌鏈路跟蹤，在大部分情況下基本上已經夠用了，當然你也可以引入SkyWalking或ZipKin等探針框架，它們提供的功能也更全面更豐富。如何選擇，需要根據具體項目自行權衡。
