Spring Boot 中使用自定義注解，AOP 切面打印出入參日志及Dubbo鏈路追蹤透傳traceId

一、使用背景

開發排查系統問題用得最多的手段就是查看系統日志，在分布式環境中一般使用 ELK 來統一收集日志，但是在並發大時使用日志定位問題還是比較麻煩，由於大量的其他用戶/其他線程的日志也一起輸出穿行其中導致很難篩選出指定請求的全部相關日志，以及下游線程/服務對應的日志。

二、解決思路

每個請求都使用一個唯一標識來追蹤全部的鏈路顯示在日志中，並且不修改原有的

使用Logback的MDC機制日志模板中加入traceId標識，取值方式為%X{traceId}

MDC(Mapped Diagnostic Context，映射調試上下文)是 log4j 和 logback 提供的一種方便在多線程條件下記錄日志的功能。MDC 可以看成是一個與當前線程綁定的Map，可以往其中添加鍵值對。MDC 中包含的內容可以被同一線程中執行的代碼所訪問。當前線程的子線程會繼承其父線程中的 MDC 的內容。當需要記錄日志時，只需要從 MDC 中獲取所需的信息即可。MDC 的內容則由程序在適當的時候保存進去。對於一個 Web 應用來說，通常是在請求被處理的最開始保存這些數據。

三、方案實現

由於MDC內部使用的是ThreadLocal所以只有本線程才有效，子線程和下游的服務MDC里的值會丟失;所以方案主要的難點是解決值的傳遞問題。

1.logback配置文件模板格式添加標識%X{traceId}

 <!--格式化輸出：%d表示日期，%thread表示線程名，%-5level：級別從左顯示5個字符寬度%msg：日志消息，%n是換行符--> <property name="log.pattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%thread] %-5level %logger{20} - [%method,%line] - %msg%n" /> 

2.添加AOP maven依賴

<dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-aop</artifactId> </dependency> 

3.自定義日志注解

import java.lang.annotation.*; /** * @Description: 自定義日志注解 */ //什么時候使用該注解，我們定義為運行時 @Retention(RetentionPolicy.RUNTIME) //注解用於什么地方，我們定義為作用於方法上 @Target({ElementType.METHOD}) //注解是否將包含在 JavaDoc 中 @Documented public @interface WebLog { /** * 日志描述信息 * * @return */ String description() default ""; } 

4.配置AOP切面

在配置 AOP 切面之前，我們需要了解下 aspectj 相關注解的作用：

• @Aspect：聲明該類為一個注解類；
• @Pointcut：定義一個切點，后面跟隨一個表達式，表達式可以定義為切某個注解，也可以切某個 package 下的方法；

切點定義好后，就是圍繞這個切點做文章了：

• @Before: 在切點之前，織入相關代碼；
• @After: 在切點之后，織入相關代碼;
• @AfterReturning: 在切點返回內容后，織入相關代碼，一般用於對返回值做些加工處理的場景；
• @AfterThrowing: 用來處理當織入的代碼拋出異常后的邏輯處理;
• @Around: 環繞，可以在切入點前后織入代碼，並且可以自由的控制何時執行切點；

import com.alibaba.dubbo.rpc.RpcContext; import com.google.gson.Gson; import com.common.annotation.WebLog; import com.common.constant.Constants; import lombok.extern.slf4j.Slf4j; import org.aspectj.lang.JoinPoint; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.*; import org.slf4j.MDC; import org.springframework.core.annotation.Order; import org.springframework.stereotype.Component; import org.springframework.web.context.request.RequestContextHolder; import org.springframework.web.context.request.ServletRequestAttributes; import javax.servlet.http.HttpServletRequest; import java.lang.reflect.Method; import java.util.UUID; @Component @Aspect @Order(1) @Slf4j public class WebLogAspect { /** * 換行符 */ private static final String LINE_SEPARATOR = System.lineSeparator(); /** * 以自定義 @WebLog 注解為切點 */ @Pointcut("@annotation(com.pet.common.annotation.WebLog)") public void WebLogAspect() { } /** * 在切點之前織入 * * @param joinPoint * @throws Throwable */ @Before("WebLogAspect()") public void doBefore(JoinPoint joinPoint) throws Throwable { // 開始打印請求日志 ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes(); HttpServletRequest request = attributes.getRequest(); // 獲取 @WebLog 注解的描述信息 String methodDescription = getAspectLogDescription(joinPoint); String traceId = String.valueOf(UUID.randomUUID()); MDC.put(Constants.LOG_TRACE_ID, traceId); RpcContext.getContext().setAttachment(Constants.LOG_TRACE_ID,traceId); // 打印請求相關參數 log.info("========================================== Start =========================================="); // 打印請求 url log.info("URL : {}", request.getRequestURL().toString()); // 打印描述信息 log.info("Description : {}", methodDescription); // 打印 Http method log.info("HTTP Method : {}", request.getMethod()); // 打印調用 controller 的全路徑以及執行方法 log.info("Class Method : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName()); // 打印請求的 IP log.info("IP : {}", request.getRemoteAddr()); // 打印請求入參 log.info("Request Args : {}", new Gson().toJson(joinPoint.getArgs())); } /** * 在切點之后織入 * * @throws Throwable */ @After("WebLogAspect()") public void doAfter() throws Throwable { // 接口結束后換行，方便分割查看 log.info("=========================================== End ===========================================" + LINE_SEPARATOR); MDC.clear(); } /** * 環繞 * * @param proceedingJoinPoint * @return * @throws Throwable */ @Around("WebLogAspect()") public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable { long startTime = System.currentTimeMillis(); Object result = null; try { result = proceedingJoinPoint.proceed(); } catch (Exception e) { log.info("exception :{}", e.getMessage()); throw e; } finally { // 打印出參 log.info("Response Args : {}", new Gson().toJson(result)); // 執行耗時 log.info("Time-Consuming : {} ms", System.currentTimeMillis() - startTime); } return result; } /** * 獲取切面注解的描述 * * @param joinPoint 切點 * @return 描述信息 * @throws Exception */ public String getAspectLogDescription(JoinPoint joinPoint) throws Exception { String targetName = joinPoint.getTarget().getClass().getName(); String methodName = joinPoint.getSignature().getName(); Object[] arguments = joinPoint.getArgs(); Class targetClass = Class.forName(targetName); Method[] methods = targetClass.getMethods(); StringBuilder description = new StringBuilder(""); for (Method method : methods) { if (method.getName().equals(methodName)) { Class[] clazzs = method.getParameterTypes(); if (clazzs.length == arguments.length) { description.append(method.getAnnotation(WebLog.class).description()); break; } } } return description.toString(); } 

5.下游dubbo服務創建DubboTraceFilter過濾器 服務者端提供擴展

資源文件夾下創建 META-INF/dubbo 文件夾 創建com.alibaba.dubbo.rpc.Filter 文件，並編輯文件內容

// xxx為你DubboTraceIdFilter文件所在的位置
dubboTraceIdFilter=com.xxx.DubboTraceIdFilter

import com.alibaba.dubbo.common.extension.Activate; import com.alibaba.dubbo.rpc.*; import org.slf4j.MDC; /**  * @Description: dubbo跟蹤traceId */ @Activate(group = {com.alibaba.dubbo.common.Constants.CONSUMER, com.alibaba.dubbo.common.Constants.PROVIDER}) public class DubboTraceIdFilter implements Filter { private static final String LOG_TRACE_ID = "traceId"; @Override public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException { RpcContext rpcContext = RpcContext.getContext(); // before if (rpcContext.isProviderSide()) { // get traceId from dubbo consumer，and set traceId to MDC String traceId = rpcContext.getAttachment(LOG_TRACE_ID); MDC.put(LOG_TRACE_ID, traceId); } if (rpcContext.isConsumerSide()) { // get traceId from MDC, and set traceId to rpcContext String traceId = MDC.get(LOG_TRACE_ID); rpcContext.setAttachment(LOG_TRACE_ID, traceId); } Result result = invoker.invoke(invocation); // after if (rpcContext.isProviderSide()) { // clear traceId from MDC MDC.remove(LOG_TRACE_ID); } return result; } 

四、如何使用

因為我們的切點是自定義注解 @WebLog, 所以我們僅僅需要在 Controller 控制器的每個接口方法添加 @WebLog 注解即可，如果我們不想某個接口打印出入參日志，不加注解就可以了

五、打印效果

從上圖中可以看到，每個對於每個請求，開始與結束一目了然，並且打印了以下參數：

• URL: 請求接口地址；
• Description: 接口的中文說明信息；
• HTTP Method: 請求的方法，是 POST, GET, 還是 DELETE 等；
• Class Method: 被請求的方法路徑 : 包名 + 方法名;
• IP: 請求方的 IP 地址；
• Request Args: 請求入參，以 JSON 格式輸出；
• Response Args: 響應出參，以 JSON 格式輸出；
• Time-Consuming: 請求耗時，以此估算每個接口的性能指數；