原文連結：基於SLF4J的MDC機制和Dubbo的Filter機制，實現分散式系統的日誌全鏈路追蹤
一、日誌系統
1、日誌框架
在每個系統應用中，我們都會使用日誌系統，主要是為了記錄必要的資訊和方便排查問題。
而現在主流的就是 SLF4J + Logback。
當我們的系統是單體應用，日誌做起來時非常簡單的，直接使用 log.info,log.error,log.warn 等等方法。
而當我們的系統是分散式系統，服務之間通訊通常都是使用 Dubbo 這個 RPC 框架。
此時做日誌就不是這麼簡單了，因為不同服務都是不同的例項，日誌就無法做到一起了，怎麼將服務間的呼叫串聯起來，也是一個問題。
但是呢，SLF4J 提供了一個 MDC 機制，它的設計目標就是為了應對分散式應用系統的審計和除錯。
所以，我們可以利用 MDC ，然後配合 Dubbo 的 RpcContext 來做分散式系統的全鏈路日誌功能。
2、搭建日誌系統
前提：我們使用的是 Spring Boot 專案。
Spring Boot 引入日誌依賴：
<!-- log begin -->
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-core</artifactId>
</dependency>
<dependency>
<groupId>com.alibaba</groupId>
<artifactId>fastjson</artifactId>
<version>1.2.68</version>
</dependency>
<!-- log end -->
加入 Logback 的 xml 配置檔案：
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<!-- 程式服務名 -->
<springProperty scope="context" name="SERVICE_NAME" source="spring.application.name" defaultValue="unknown"/>
<!-- 定義日誌的根目錄 -->
<springProperty scope="context" name="LOG_PATH" source="logging.file.path" defaultValue="/Users/howinfun/weblog/java/${SERVICE_NAME}"/>
<!-- 日誌輸出格式 -->
<springProperty scope="context" name="LOG_PATTERN" source="logging.pattern" defaultValue="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%-5level] [%logger{5}] [%X{uri}] [%X{trace_id}] - %msg%n"/>
<!-- 控制檯輸出 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<!--格式化輸出：%d表示日期，%thread表示執行緒名，%-5level：級別從左顯示5個字元寬度%msg：日誌訊息，%n是換行符-->
<pattern>${LOG_PATTERN}</pattern>
</layout>
<!--此日誌appender是為開發使用，只配置最底級別，控制檯輸出的日誌級別是大於或等於此級別的日誌資訊-->
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>debug</level>
</filter>
<encoder>
<Pattern>${LOG_PATTERN}</Pattern>
<!-- 設定字符集 -->
<charset>UTF-8</charset>
</encoder>
</appender>
// .... 還有各種 Info、Warn、Error 等日誌配置
<!-- 日誌輸出級別 -->
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
上面的註釋已經寫得非常的清晰了，而我們最主要關注的就是LOG_PATTERN 這個屬性。它主要是規定了日誌列印的規範，如何列印日誌，日誌該帶上哪些關鍵資訊。
[%X{uri}]：這裡主要是記錄介面的請求 uri。[%X{trace_id}]：這裡主要是記錄此次請求的 TraceId，這個 TraceId 也會帶到 Dubbo 的服務提供端，讓整個鏈路都帶上這個 TraceId。這樣在日誌記錄的時候，全都可以利用 TraceId 了。
這樣等到日誌排查的時候，只需要前端或者測試給後端的同學提供一個 TraceId，我們就能非常快速的定位到問題所在了。
下面的專案都是引入上面的依賴和加入 xml 檔案即可。
二、專案搭建
接下來我們會建立四個專案，分別是 dubbo-api（提供API和工具類）、dubbo-provider-one（Dubbo 服務提供者1）、dubbo-provider-two（Dubbo 服務提供者2）、dubbo-consumer（Dubbo 服務消費者，對外提供 HTTP 介面）。
1、dubbo-api：
這裡面最重要的是 TraceUtil 工具類。
這個工具類提供了幾個很重要的方法：
- TraceId 的初始化：生成 TraceId，並利用 MDC 將 Trace 相關資訊存放在當前執行緒（請求）的 ThreaLocal 中。
- TraceId 的存放：將當前執行緒（請求）的 Trace 相關資訊存放在 Dubbo 的 RPC 上下文 RpcContext 中，這樣可以將當前請求的 Trace 資訊傳遞到 Dubbo 的服務提供者。
- TraceId 的獲取：當然了，Dubbo 的服務提供者也可以利用這工具類，從 RpcContext 中獲取 Trace 資訊。
下面直接上程式碼：
/**
* Trace 工具
* @author winfun
* @date 2020/10/30 9:02 上午
**/
public class TraceUtil {
public final static String TRACE_ID = "trace_id";
public final static String TRACE_URI = "uri";
/**
* 初始化 TraceId
* @param uri 請求uri
*/
public static void initTrace(String uri) {
if(StringUtils.isBlank(MDC.get(TRACE_ID))) {
String traceId = generateTraceId();
setTraceId(traceId);
MDC.put(TRACE_URI, uri);
}
}
/**
* 從 RpcContext 中獲取 Trace 相關資訊，包括 TraceId 和 TraceUri
* 給 Dubbo 服務端呼叫
* @param context Dubbo 的 RPC 上下文
*/
public static void getTraceFrom(RpcContext context) {
String traceId = context.getAttachment(TRACE_ID);
if (StringUtils.isNotBlank(traceId)){
setTraceId(traceId);
}
String uri = context.getAttachment(TRACE_URI);
if (StringUtils.isNotEmpty(uri)) {
MDC.put(TRACE_URI, uri);
}
}
/**
* 將 Trace 相關資訊，包括 TraceId 和 TraceUri 放入 RPC上下文中
* 給 Dubbo 消費端呼叫
* @param context Dubbo 的 RPC 上下文
*/
public static void putTraceInto(RpcContext context) {
String traceId = MDC.get(TRACE_ID);
if (StringUtils.isNotBlank(traceId)) {
context.setAttachment(TRACE_ID, traceId);
}
String uri = MDC.get(TRACE_URI);
if (StringUtils.isNotBlank(uri)) {
context.setAttachment(TRACE_URI, uri);
}
}
/**
* 從 MDC 中清除當前執行緒的 Trace資訊
*/
public static void clearTrace() {
MDC.clear();
}
/**
* 將traceId放入MDC
* @param traceId 鏈路ID
*/
private static void setTraceId(String traceId) {
traceId = StringUtils.left(traceId, 36);
MDC.put(TRACE_ID, traceId);
}
/**
* 生成traceId
* @return 鏈路ID
*/
private static String generateTraceId() {
return TraceIdUtil.nextNumber();
}
}
2、dubbo-consumer
專案結構如下：
專案是基於 Spring Boot 框架搭建的，使用 dubbo-spring-boot-starter 整合 Dubbo 框架。
WebRequestFilter：
首先，利用 @WebFilter，攔截所有 Http 請求，然後利用 TraceUtil 給這個請求初始化對應的 Trace 資訊，然後將 Trace 資訊利用 SLF4J 提供的 MDC 機制存放起來。之後利用 Logger 打日誌的時候，會帶上 Trace 資訊。
下面上程式碼：
/**
* Web Request Filter
* @author winfun
* @date 2020/10/30 3:02 下午
**/
@Slf4j
@Order(1)
@WebFilter(urlPatterns = "/*")
public class WebRequestFilter implements Filter {
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
HttpServletRequest request = (HttpServletRequest) servletRequest;
HttpServletResponse response = (HttpServletResponse) servletResponse;
String uri = request.getRequestURI();
// 初始化 TraceId
TraceUtil.initTrace(uri);
filterChain.doFilter(request,response);
// 清除 TraceId 和 TraceUri
TraceUtil.clearTrace();
}
}
DubboTraceFilter：
接著，我們利用 Dubbo 提供的 Filter 機制，在每次進行 Dubbo 呼叫的前後，進行日誌列印。
在過濾器的最開始，首先會處理 Trace 相關資訊：
- 如果是當前呼叫時消費者的話，主動從 MDC 中獲取 Trace 資訊並放入 RpcContext 中，這樣可以將 Trace 資訊傳遞到服務提供者那邊。
- 如果當前是服務提供者，則可以從 RpcContext 中獲取 Trace 資訊，接著利用 MDC 將 Trace 資訊儲存起來。
下面上程式碼：
/**
* Dubbo Trace Filter
* @author winfun
* @date 2020/10/30 9:46 上午
**/
@Slf4j
@Activate(order = 100,group = {Constants.PROVIDER_PROTOCOL,Constants.CONSUMER_PROTOCOL})
public class DubboTraceFilter implements Filter {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
// 處理 Trace 資訊
printRequest(invocation);
// 執行前
handleTraceId();
long start = System.currentTimeMillis();
Result result = invoker.invoke(invocation);
long end = System.currentTimeMillis();
// 執行後
printResponse(invocation,result,end-start);
return result;
}
/***
* 列印請求
* @author winfun
* @param invocation invocation
* @return {@link }
**/
private void printRequest(Invocation invocation){
DubboRequestDTO requestDTO = new DubboRequestDTO();
requestDTO.setInterfaceClass(invocation.getInvoker().getInterface().getName());
requestDTO.setMethodName(invocation.getMethodName());
requestDTO.setArgs(getArgs(invocation));
log.info("call Dubbo Api start , request is {}",requestDTO);
}
/***
* 列印結果
* @author winfun
* @param invocation invocation
* @param result result
* @return {@link }
**/
private void printResponse(Invocation invocation,Result result,long spendTime){
DubboResponseDTO responseDTO = new DubboResponseDTO();
responseDTO.setInterfaceClassName(invocation.getInvoker().getInterface().getName());
responseDTO.setMethodName(invocation.getMethodName());
responseDTO.setResult(JSON.toJSONString(result.getValue()));
responseDTO.setSpendTime(spendTime);
log.info("call Dubbo Api end , response is {}",responseDTO);
}
/***
* 獲取 Invocation 引數，過濾掉大引數
* @author winfun
* @param invocation invocation
* @return {@link Object[] }
**/
private Object[] getArgs(Invocation invocation){
Object[] args = invocation.getArguments();
args = Arrays.stream(args).filter(arg->{
if (arg instanceof byte[] || arg instanceof Byte[] || arg instanceof InputStream || arg instanceof File){
return false;
}
return true;
}).toArray();
return args;
}
/***
* 處理 TraceId，如果當前物件是服務消費者，則將 Trace 資訊放入 RpcContext中
* 如果當前物件是服務提供者，則從 RpcContext 中獲取 Trace 資訊。
* @author winfun
* @return {@link }
**/
private void handleTraceId() {
RpcContext context = RpcContext.getContext();
if (context.isConsumerSide()) {
TraceUtil.putTraceInto(context);
} else if (context.isProviderSide()) {
TraceUtil.getTraceFrom(context);
}
}
}
ResponseBodyAdvice：
還有一個比較重要的點是，我們需要在介面返回時將 TraceId 返回給前端，我們當然不可能在每個介面那裡植入返回 TraceId 的程式碼，而是利用 ResponseBodyAdvice，可以在介面結果返回前，對返回結果進行進一步的處理。
下面上程式碼：
/**
* Response Advice
* @author winfun
* @date 2020/10/30 3:47 下午
**/
@RestControllerAdvice(basePackages = "com.winfun")
public class WebResponseModifyAdvice implements ResponseBodyAdvice {
@Override
public boolean supports(final MethodParameter methodParameter, final Class converterType) {
// 返回 class 為 ApiResult（帶 TraceId 屬性） & converterType 為 Json 轉換
return methodParameter.getMethod().getReturnType().isAssignableFrom(ApiResult.class)
&& converterType.isAssignableFrom(MappingJackson2HttpMessageConverter.class);
}
@Override
public Object beforeBodyWrite(final Object body, final MethodParameter methodParameter, final MediaType mediaType, final Class aClass,
final ServerHttpRequest serverHttpRequest, final ServerHttpResponse serverHttpResponse) {
// 設定 TraceId
((ApiResult<?>) body).setTraceId(MDC.get(TraceUtil.TRACE_ID));
return body;
}
}
3、dubbo-provider-one & dubbo-provider-two
服務提供者也是非常的簡單，同樣只需要使用上面消費者的 DubboTraceFiler 即可，裡面會先從 RpcContext 中獲取 Trace 資訊，然後將 Dubbo 呼叫前的 Request 和呼叫後的 Response 都列印出來。就沒有其他多餘的動作了。
三、測試
1、介面如下：
介面非常簡單，直接引入兩個服務提供者的依賴，然後進行 Dubbo 介面的呼叫，最後將倆介面的返回值拼接起來返回給前端即可。
下面上程式碼：
/**
* Say Hello & Hi
* @author winfun
* @date 2020/10/29 5:12 下午
**/
@RequestMapping("/hello")
@RestController
public class HelloController {
@DubboReference(check = false,lazy = true)
private DubboServiceOne dubboServiceOne;
@DubboReference(check = false,lazy = true)
private DubboServiceTwo dubboServiceTwo;
@GetMapping("/{name}")
public ApiResult sayHello(@PathVariable("name") String name){
String hello = dubboServiceOne.sayHello(name);
String hi = dubboServiceTwo.sayHi(name);
return ApiResult.success(hello+" "+hi);
}
}
2、介面返回：
我們可以看到介面已經成功返回，並且可以看到 TraceId 為16042841032799628772：
接下來，我們看看消費者的後臺列印是否是同一個 TraceId，無疑是一樣的：
最後，我們要確定兩個服務提供者是否能拿到對應的 Trace 資訊：
服務提供者One：
服務提供者Two：
到此，我們可以發現：不管是前端，Dubbo 消費者，和 Dubbo 提供者，都是同一個 TraceId。這樣的話，我們整個日誌鏈路就跑通了。
四、最後
當然了，上面的日誌全鏈路追蹤只適合用於 Dubbo 作為 PRC 框架。假設我們使用 OpenFeign 的話，只能自己再做擴充套件了。
雖然專案程式碼不多，但是就不全部放上來了，如果大家感興趣，可以去看看：全鏈路日誌記錄