引言

在日常的后端開發工作中，最常見的操作之一就是看日志排查問題，對于大項目一般使用類似ELK的技術棧統一搜集日志，小項目就直接把日志打印到日志文件。那不管對于大項目或者小項目，查看日志都需要通過某個關鍵字進行搜索，從而快速定位到異常日志的位置來進一步排查問題。

對于后端初學者來說，日志的關鍵字可能就是直接打印某個業務的說明加上業務標識，如果出現問題直接搜索對應的說明或者標識。例如下單場景，可能就直接打印:創建訂單，訂單編號:xxxx，當有問題的時候，則直接搜索訂單編號或者創建訂單。在這種方式下，經常會搜索出多條日志，增加問題的排查時長。

所以，今天我們就來說一說這個關鍵字的設計，這里我們使用RequestId進行精確定位問題日志的位置從而解決問題。

需求

目標： 幫助開發快速定位日志位置

思路：當前端進行一次請求的時候，在進行業務邏輯處理之前我們需要生成一個唯一的RequestId，在業務邏輯處理過程中涉及到日志打印我們都需要帶上這個RequestId，最后響應給前端的數據結構同樣需要帶上RequestId。 這樣，每次請求都會有一個RequestId，當某個接口異常則通過前端反饋的RequestId，后端即可快速定位異常的日志位置。

總結下我們的需求：

• 一次請求生成一次RequestId，并且RequestId唯一
• 一次請求響應給前端，都需要返回RequestId字段，接口正常、業務異常、系統異常，都需要返回該字段
• 一次請求在控制臺或者日志文件打印的日志，都需要顯示RequestId
• 一次請求的入參和出參都需要打印
• 對于異步操作，需要在異步線程的日志同樣顯示RequestId

實現

1. 實現生成和存儲RequestId的工具類

public class RequestIdUtils {
    private static final ThreadLocal<UUID> requestIdHolder = new ThreadLocal<>();
    private RequestIdUtils() {
    }
    public static void generateRequestId() {
        requestIdHolder.set(UUID.randomUUID());
    }
    public static void generateRequestId(UUID uuid) {
        requestIdHolder.set(uuid);
    }
    public static UUID getRequestId() {
        return (UUID)requestIdHolder.get();
    }
    public static void removeRequestId() {
        requestIdHolder.remove();
    }
}

因為我們一次請求會生成一次RequestId，并且RequestId唯一，所以這里我們使用使用UUID來生成RequestId，并且用ThreadLocal進行存儲。

2. 實現一個AOP，攔截所有的Controller的方法，這里是主要的處理邏輯

@Aspect
@Order
@Slf4j
public class ApiMessageAdvisor {


    @Around("execution(public * org.anyin.gitee.shiro.controller..*Controller.*(..))")
    public Object invokeAPI(ProceedingJoinPoint pjp) {
        String apiName = this.getApiName(pjp);
        // 生成RequestId
        String requestId = this.getRequestId();
        // 配置日志文件打印 REQUEST_ID
        MDC.put("REQUEST_ID", requestId);
        Object returnValue = null;
        try{
            // 打印請求參數
            this.printRequestParam(apiName, pjp);
            returnValue = pjp.proceed();
            // 處理RequestId
            this.handleRequestId(returnValue);
        }catch (BusinessException ex){
            // 業務異常
            returnValue = this.handleBusinessException(apiName, ex);
        }catch (Throwable ex){
            // 系統異常        
            returnValue = this.handleSystemException(apiName, ex);
        }finally {
            // 打印響應參數
            this.printResponse(apiName, returnValue);
            RequestIdUtils.removeRequestId();
            MDC.clear();
        }
        return returnValue;
    }

    /**
     * 處理系統異常
     * @param apiName 接口名稱
     * @param ex 系統異常
     * @return 返回參數
     */
    private Response handleSystemException(String apiName, Throwable ex){
        log.error("@Meet unknown error when do " + apiName + ":" + ex.getMessage(), ex);
        Response response = new Response(BusinessCodeEnum.UNKNOWN_ERROR.getCode(), BusinessCodeEnum.UNKNOWN_ERROR.getMsg());
        response.setRequestId(RequestIdUtils.getRequestId().toString());
        return response;
    }

    /**
     * 處理業務異常
     * @param apiName 接口名稱
     * @param ex 業務異常
     * @return 返回參數
     */
    private Response handleBusinessException(String apiName, BusinessException ex){
        log.error("@Meet error when do " + apiName + "[" + ex.getCode() + "]:" + ex.getMsg(), ex);
        Response response = new Response(ex.getCode(), ex.getMsg());
        response.setRequestId(RequestIdUtils.getRequestId().toString());
        return response;
    }

    /**
     * 填充RequestId
     * @param returnValue 返回參數
     */
    private void handleRequestId(Object returnValue){
        if(returnValue instanceof Response){
            Response response = (Response)returnValue;
            response.setRequestId(RequestIdUtils.getRequestId().toString());
        }
    }

    /**
     * 打印響應參數信息
     * @param apiName 接口名稱
     * @param returnValue 返回值
     */
    private void printResponse(String apiName, Object returnValue){
        if (log.isInfoEnabled()) {
            log.info("@@{} done, response: {}", apiName, JSONUtil.toJsonStr(returnValue));
        }
    }

    /**
     * 打印請求參數信息
     * @param apiName 接口名稱
     * @param pjp 切點
     */
    private void printRequestParam(String apiName, ProceedingJoinPoint pjp){
        Object[] args = pjp.getArgs();
        if(log.isInfoEnabled() && args != null&& args.length > 0){
            for(Object o : args) {
                if(!(o instanceof HttpServletRequest) && !(o instanceof HttpServletResponse) && !(o instanceof CommonsMultipartFile)) {
                    log.info("@@{} started, request: {}", apiName, JSONUtil.toJsonStr(o));
                }
            }
        }
    }

    /**
     * 獲取RequestId
     * 優先從header頭獲取，如果沒有則自己生成
     * @return RequestId
     */
    private String getRequestId(){
        // 因為如果有網關，則一般會從網關傳遞過來，所以優先從header頭獲取
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        if(attributes != null && StringUtils.hasText(attributes.getRequest().getHeader("x-request-id"))) {
            HttpServletRequest request = attributes.getRequest();
            String requestId = request.getHeader("x-request-id");
            UUID uuid = UUID.fromString(requestId);
            RequestIdUtils.generateRequestId(uuid);
            return requestId;
        }
        UUID existUUID = RequestIdUtils.getRequestId();
        if(existUUID != null){
            return existUUID.toString();
        }
        RequestIdUtils.generateRequestId();
        return RequestIdUtils.getRequestId().toString();
    }

    /**
     * 獲取當前接口對應的類名和方法名
     * @param pjp 切點
     * @return apiName
     */
    private String getApiName(ProceedingJoinPoint pjp){
        String apiClassName = pjp.getTarget().getClass().getSimpleName();
        String methodName = pjp.getSignature().getName();
        return apiClassName.concat(":").concat(methodName);
    }
}

簡單說明：

• 對于RequestId的獲取方法 getRequestId，我們優先從header頭獲取，有網關的場景下一般會從網關傳遞過來；其次判斷是否已經存在，如果存在則直接返回，這里是為了兼容有過濾器并且在過濾器生成了RequestId的場景；最后之前2中場景都未找到RequestId，則自己生成，并且返回
• MDC.put("REQUEST_ID", requestId) 在我們生成RequestId之后，需要設置到日志系統中，這樣子日志文件才能打印RequestId
• printRequestParam 和 printResponse 是打印請求參數和響應參數，如果是高并發或者參數很多的場景下，最好不要打印
• handleRequestId 、 handleBusinessException 、 handleSystemException 這三個方法分別是在接口正常、接口業務異常、接口系統異常的場景下設置RequestId

3. 日志文件配置

<contextName>logback</contextName>
<springProperty scope="context" name="level" source="logging.level.root"/>
<springProperty scope="context" name="path" source="logging.file.path"/>


<Appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <Target>System.out</Target>
   <filter class="ch.qos.logback.classic.filter.ThresholdFilter" >
        <level>DEBUG</level>
    </filter>
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{REQUEST_ID}] [%thread] [%-5level] [%logger{0}:%L] : %msg%n</pattern>
    </encoder>
</appender>

<appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${path}</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${path}.%d{yyyy-MM-dd}.zip</fileNamePattern>
    </rollingPolicy>
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{REQUEST_ID}] [%thread] [%-5level] [%logger{0}:%L] : %msg%n</pattern>
    </encoder>
</appender>

<root level="${level}">
    <appender-ref ref="console"/>
    <appender-ref ref="file"/>
</root>

這里是一個簡單的日志格式配置文件，主要是關注[%X{REQUEST_ID}], 這里主要是把RequestId在日志文件中打印出來

4. 解決線程異步場景下RequestId的打印問題

public class MdcExecutor implements Executor {
    private Executor executor;
    public MdcExecutor(Executor executor) {
        this.executor = executor;
    }
    @Override
    public void execute(Runnable command) {
        final String requestId = MDC.get("REQUEST_ID");
        executor.execute(() -> {
            MDC.put("REQUEST_ID", requestId);
            try {
                command.run();
            } finally {
                MDC.remove("REQUEST_ID");
            }
        });
    }
}

這里是一個簡單的代理模式，代理了Executor，在真正執行的run方法之前設置RequestId到日志系統中，這樣子異步線程的日志同樣可以打印我們想要的RequestId

測試效果

• 登錄效果

• 正常的業務處理

• 發生業務異常

• 發生系統異常

• 異步線程

最后

通過以上騷操作，同學，你知道怎么使用RequestId看日志了嗎？