不会吧，你还不会用RequestId看日志 ?

引言

在日常的后端开发工作中，最常见的操作之一就是看日志排查问题，对于大项目一般使用类似ELK的技术栈统一搜集日志，小项目就直接把日志打印到日志文件。那不管对于大项目或者小项目，查看日志都需要通过某个关键字进行搜索，从而快速定位到异常日志的位置来进一步排查问题。

对于后端初学者来说，日志的关键字可能就是直接打印某个业务的说明加上业务标识，如果出现问题直接搜索对应的说明或者标识。例如下单场景，可能就直接打印:创建订单，订单编号:xxxx，当有问题的时候，则直接搜索订单编号或者创建订单。在这种方式下，经常会搜索出多条日志，增加问题的排查时长。

所以，今天我们就来说一说这个关键字的设计，这里我们使用RequestId进行精确定位问题日志的位置从而解决问题。

需求

目标：帮助开发快速定位日志位置

思路：当前端进行一次请求的时候，在进行业务逻辑处理之前我们需要生成一个唯一的RequestId，在业务逻辑处理过程中涉及到日志打印我们都需要带上这个RequestId，最后响应给前端的数据结构同样需要带上RequestId。这样，每次请求都会有一个RequestId，当某个接口异常则通过前端反馈的RequestId，后端即可快速定位异常的日志位置。

总结下我们的需求：

一次请求生成一次RequestId，并且RequestId唯一
一次请求响应给前端，都需要返回RequestId字段，接口正常、业务异常、系统异常，都需要返回该字段
一次请求在控制台或者日志文件打印的日志，都需要显示RequestId
一次请求的入参和出参都需要打印
对于异步操作，需要在异步线程的日志同样显示RequestId

实现

实现生成和存储RequestId的工具类

java复制代码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进行存储。

实现一个AOP，拦截所有的Controller的方法，这里是主要的处理逻辑

java复制代码@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

日志文件配置

xml复制代码<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在日志文件中打印出来

解决线程异步场景下RequestId的打印问题

java复制代码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");
            }
        });
    }
}