#原文連結：[基於SLF4J的MDC機制和Dubbo的Filter機制，實現分散式系統的日誌全鏈路追蹤](https://blog.csdn.net/Howinfun/article/details/109478879) # 一、日誌系統 ## 1、日誌框架 在每個系統應用中，我們都會使用日誌系統，主要是為了記錄必要的資訊和方便排查問題。 而現在主流的就是 SLF4J + Logback。 當我們的系統是單體應用，日誌做起來時非常簡單的，直接使用 `log.info`,`log.error`,`log.warn` 等等方法。 而當我們的系統是分散式系統，服務之間通訊通常都是使用 Dubbo 這個 RPC 框架。 此時做日誌就不是這麼簡單了，因為不同服務都是不同的例項，日誌就無法做到一起了，怎麼將服務間的呼叫串聯起來，也是一個問題。 但是呢，SLF4J 提供了一個 [MDC](https://www.jianshu.com/p/1dea7479eb07) 機制，它的設計目標就是為了應對分散式應用系統的審計和除錯。 **所以，我們可以利用 MDC ，然後配合 Dubbo 的 RpcContext 來做分散式系統的全鏈路日誌功能。** ## 2、搭建日誌系統 前提：我們使用的是 Spring Boot 專案。 **Spring Boot 引入日誌依賴：** ```xml org.slf4j slf4j-api ch.qos.logback logback-core com.alibaba fastjson 1.2.68 ``` **加入 Logback 的 xml 配置檔案：** ```xml ${LOG_PATTERN} debug ${LOG_PATTERN}

UTF-8 // .... 還有各種 Info、Warn、Error 等日誌配置 ``` 上面的註釋已經寫得非常的清晰了，而我們最主要關注的就是`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 資訊。 **下面直接上程式碼：** ```java /** * 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](https://github.com/alibaba/dubbo-spring-boot-starter) 整合 Dubbo 框架。  ### WebRequestFilter： 首先，利用 @WebFilter，攔截所有 Http 請求，然後利用 TraceUtil 給這個請求初始化對應的 Trace 資訊，然後將 Trace 資訊利用 SLF4J 提供的 MDC 機制存放起來。之後利用 Logger 打日誌的時候，會帶上 Trace 資訊。 **下面上程式碼：** ```java /** * 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 資訊儲存起來。 **下面上程式碼：** ```java /** * 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，可以在介面結果返回前，對返回結果進行進一步的處理。 **下面上程式碼：** ```java /** * 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 介面的呼叫，最後將倆介面的返回值拼接起來返回給前端即可。 **下面上程式碼：** ```java /** * 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 的話，只能自己再做擴充套件了。 雖然專案程式碼不多，但是就不全部放上來了，如果大家感興趣，可以去看看：[全鏈路日誌記錄](https://github.com/Howinfun/study-in-work-and-life/tree/master