引言

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

對(duì)于后端初學(xué)者來說，日志的關(guān)鍵字可能就是直接打印某個(gè)業(yè)務(wù)的說明加上業(yè)務(wù)標(biāo)識(shí)，如果出現(xiàn)問題直接搜索對(duì)應(yīng)的說明或者標(biāo)識(shí)。例如下單場(chǎng)景，可能就直接打印:創(chuàng)建訂單，訂單編號(hào):xxxx，當(dāng)有問題的時(shí)候，則直接搜索訂單編號(hào)或者創(chuàng)建訂單。在這種方式下，經(jīng)常會(huì)搜索出多條日志，增加問題的排查時(shí)長(zhǎng)。

所以，今天我們就來說一說這個(gè)關(guān)鍵字的設(shè)計(jì)，這里我們使用RequestId進(jìn)行精確定位問題日志的位置從而解決問題。

需求

目標(biāo)：幫助開發(fā)快速定位日志位置

思路：當(dāng)前端進(jìn)行一次請(qǐng)求的時(shí)候，在進(jìn)行業(yè)務(wù)邏輯處理之前我們需要生成一個(gè)唯一的RequestId，在業(yè)務(wù)邏輯處理過程中涉及到日志打印我們都需要帶上這個(gè)RequestId，最后響應(yīng)給前端的數(shù)據(jù)結(jié)構(gòu)同樣需要帶上RequestId。這樣，每次請(qǐng)求都會(huì)有一個(gè)RequestId，當(dāng)某個(gè)接口異常則通過前端反饋的RequestId，后端即可快速定位異常的日志位置。

總結(jié)下我們的需求：

一次請(qǐng)求生成一次RequestId，并且RequestId唯一
一次請(qǐng)求響應(yīng)給前端，都需要返回RequestId字段，接口正常、業(yè)務(wù)異常、系統(tǒng)異常，都需要返回該字段
一次請(qǐng)求在控制臺(tái)或者日志文件打印的日志，都需要顯示RequestId
一次請(qǐng)求的入?yún)⒑统鰠⒍夹枰蛴?/li>
對(duì)于異步操作，需要在異步線程的日志同樣顯示RequestId

實(shí)現(xiàn)

實(shí)現(xiàn)生成和存儲(chǔ)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();
    }
}

因?yàn)槲覀円淮握?qǐng)求會(huì)生成一次RequestId，并且RequestId唯一，所以這里我們使用使用UUID來生成RequestId，并且用ThreadLocal進(jìn)行存儲(chǔ)。

實(shí)現(xiàn)一個(gè)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{
            // 打印請(qǐng)求參數(shù)
            this.printRequestParam(apiName, pjp);
            returnValue = pjp.proceed();
            // 處理RequestId
            this.handleRequestId(returnValue);
        }catch (BusinessException ex){
            // 業(yè)務(wù)異常
            returnValue = this.handleBusinessException(apiName, ex);
        }catch (Throwable ex){
            // 系統(tǒng)異常        
            returnValue = this.handleSystemException(apiName, ex);
        }finally {
            // 打印響應(yīng)參數(shù)
            this.printResponse(apiName, returnValue);
            RequestIdUtils.removeRequestId();
            MDC.clear();
        }
        return returnValue;
    }

    /**
     * 處理系統(tǒng)異常
     * @param apiName 接口名稱
     * @param ex 系統(tǒng)異常
     * @return 返回參數(shù)
     */
    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;
    }

    /**
     * 處理業(yè)務(wù)異常
     * @param apiName 接口名稱
     * @param ex 業(yè)務(wù)異常
     * @return 返回參數(shù)
     */
    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 返回參數(shù)
     */
    private void handleRequestId(Object returnValue){
        if(returnValue instanceof Response){
            Response response = (Response)returnValue;
            response.setRequestId(RequestIdUtils.getRequestId().toString());
        }
    }

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

    /**
     * 打印請(qǐng)求參數(shù)信息
     * @param apiName 接口名稱
     * @param pjp 切點(diǎn)
     */
    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
     * 優(yōu)先從header頭獲取，如果沒有則自己生成
     * @return RequestId
     */
    private String getRequestId(){
        // 因?yàn)槿绻芯W(wǎng)關(guān)，則一般會(huì)從網(wǎng)關(guān)傳遞過來，所以優(yōu)先從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();
    }

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

簡(jiǎn)單說明：

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

日志文件配置

<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>

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

解決線程異步場(chǎng)景下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");
            }
        });
    }
}

這里是一個(gè)簡(jiǎn)單的代理模式，代理了Executor，在真正執(zhí)行的run方法之前設(shè)置RequestId到日志系統(tǒng)中，這樣子異步線程的日志同樣可以打印我們想要的RequestId