SpringBoot項目requestId生成/日志打印

原因

SpringBoot項目中的默認日志框架SLF4J，在打印日志時，每行數據都有一個請求ID，這樣會方便追蹤日志。
也可以使用一些鏈路追蹤框架來實現這種目的。

實現

SLF4J里有一個MDC類，是ThreadLocal的實現，保存在這里的變量都會綁定到某一個請求線程中，在該請求的線程里的日志代碼都可以使用設置的變量。例如：

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{REQUEST_ID}] [%thread] [%-5level] [%logger{0}:%L] : %msg%n</pattern>
其中 %X{參數名} 是引用其中的值

在項目中定義攔截器或者AOP來將攔截住所有的請求，並在MDC中設入變量。

實現步驟

我這里選擇配置的是AOP切面來實現在MDC中設入REQUEST_ID來為每一個請求添加ID。

@Aspect
@Slf4j
@Component
public class ApiMessageAdvisor {

    /**
     * 為每一個調用Controller方法的請求做一個切面
     * @param pjp
     * @return
     */
    @Around("execution(public * com.sso.controller..*Controller.*(..))")
    public Object invokeAPI(ProceedingJoinPoint pjp) {
        // 1.獲取當前接口對應的類名和方法名
        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(ResponseStatusEnum.EXCEPTION.getCode(), ResponseStatusEnum.EXCEPTION.getDesc(),ex.getMessage());
        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, JSON.toJSONString(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, JSON.toJSONString(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);
    }
}

logback-spring.xml文件

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <contextName>logback</contextName>
    <springProperty scope="context" name="level" source="logging.level.root"/>


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


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

RequestIdUtils.java

//生成全局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();
    }
}

補充

當開啟異步方法的時候，子線程獲取不到主線程的REQUEST_ID
解決方法：配置線程裝飾器
可能遇到問題：當消費MQ消息時，使用的是rabbitmq的子線程，當消費方法中有異步方法時，會導致獲取不到ThreadLocal。

/**
 * 裝飾器
 */
public class MdcTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> map = MDC.getCopyOfContextMap();
        return () -> {
            try {
                MDC.setContextMap(map);
                String requestId = MDC.get("REQUEST_ID");
                if (StringUtils.isEmpty(requestId)) {
                    requestId = UUID.randomUUID().toString();
                    MDC.put("REQUEST_ID", requestId);
                }
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }
}

@Configuration
public class ThreadPoolExecutors {
    private int corePoolSize = Runtime.getRuntime().availableProcessors() + 1;
    private int maxPoolSize = corePoolSize * 2;
    private static final int queueCapacity = 50;
    private static final int keepAliveSeconds = 30;

    @Bean(name = "threadPoolTaskExecutor")
    public ThreadPoolTaskExecutor threadPoolTaskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setMaxPoolSize(maxPoolSize);
        executor.setCorePoolSize(corePoolSize);
        executor.setQueueCapacity(queueCapacity);
        executor.setKeepAliveSeconds(keepAliveSeconds);
        // 配置裝飾器
        executor.setTaskDecorator(new MdcTaskDecorator());
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        return executor;
    }
}