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