AOP、MDC实现日志追踪

前言

在实际开发中，日志输出是非常重要的，在生产环境中，如果日志打得好，可以快速地排查问题，为了更好的查看日志，我们需要将这些日志串联起来，这样会使排查问题变得更加轻松。正好我前一篇文介绍了ELK的搭建，那么现在我们再来看看AOP+MDC如何实现日志追踪。
如果我们可以在日志中记录用户的IP，那么我们就能分析该用户的所有操作日志。如果我们可以在日志中记录订单ID，那么如果我们的订单出现了问题，我们可以很快的来根据订单ID在Kibana中搜索与该订单ID关联的所有日志信息。

实现思路

串联的核心在于要把ID作为一个请求必传参数，例如我们手动打印日志的时候，可以在日志中加上我们的业务ID，例如

1	log.info("提交订单开始：{}", orderId);

但是此种方式较为繁琐，我们需要在每条日志中都手动加上orderId的输出，那么有没有更简单的方式呢？首先想到的是AOP，因为AOP可以将日志记录的行为从业务的核心逻辑中分离出来，而MDC是一个线程安全的存放诊断日志的容器，在处理请求前将请求的唯一标示放到MDC容器中，这个唯一标示会随着日志一起输出，以此来区分该条日志是属于那个请求的。并在请求处理完成之后清除MDC容器。

public interface MDCAdapter {
    // 将一个k-v键值对放到容器，其实是放到当前线程的ThreadLocalMap中
    void put(String var1, String var2);

    // 根据key在当前线程的MDC容器中获取对应的值
    String get(String var1);

    // 根据key移除容器中的值
    void remove(String var1);

    // 清空当前线程的MDC容器
    void clear();

    Map<String, String> getCopyOfContextMap();

    void setContextMap(Map<String, String> var1);
}

Logback配置：使用MDC机制，我们需要在logback.xml日志模板中进行一些配置，通过使用占位符%X{}来占位，替换到对应MDC中key的值。

value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr([${springAppName:-}]){yellow} %clr(%X{TRACE_ID}){cyan} %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %green([%X{userIp}]) %cyan([%X{requestURI}]) %green([%X{orderId}]) %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"

我们可以通过拦截器，将用户IP信息记录到日志中

@Component
public class UserIpFilter extends OncePerRequestFilter {

    private static final String USER_IP_MDC_KEY = "userIp";
    private static final String USER_REQUEST_URI_MDC_KEY = "requestURI";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        try {
            // 获取用户IP并添加到MDC
            String userIp = request.getHeader("X-Real-IP");
            String requestURI = request.getRequestURI();
            MDC.put(USER_IP_MDC_KEY, userIp);
            MDC.put(USER_REQUEST_URI_MDC_KEY, requestURI);
            // 继续请求处理
            filterChain.doFilter(request, response);
        } finally {
            // 清除MDC，确保不会影响其他请求
            MDC.remove(USER_IP_MDC_KEY);
        }
    }
}

MDC结合AOP

因为这部分其实是半道里加进来的，所以写的比较粗糙，但是实现思路就是用切点表达式来匹配订单相关信息，主要就是Order这个实体类和orderId这个参数，但是切点不支持匹配参数名，所以匹配String orderId的时候会比较麻烦，需要一个一个手动匹配（因为不支持参数名匹配，按类型匹配会匹配第一个参数是Sting的方法，所以会匹配错）。
我这里的建议是通过方法名进行匹配，那么就需要订单相关的方法名的后缀进行统一，然后切点表达式按方法名后缀匹配就好了 ~~（后期有空再重构重构代码吧，毕竟这里写的实在不太好）~~

@Aspect
@Component
@Slf4j
public class OrderIdAspect {

    @Pointcut("(execution(* xxx.xxxx.xxx.service.OrderConsumerService.processText(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.OrderConsumerService.getPaperJsonContent(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.OrderConsumerService.getTextJsonObject(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.OrderConsumerService.TextConsumeMessage*(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.OrderConsumerService.PaperConsumeMessage*(..)))" +
            "&& args(torder, ..)")
    public void orderMethod1(Torder torder) {
    }

    @Around(value = "orderMethod1(torder)", argNames = "joinPoint,torder")
    public Object logMethod1(ProceedingJoinPoint joinPoint, Torder torder) throws Throwable {
        log.info("Accessed method: {}", joinPoint.getSignature().toShortString());
        MDC.put("orderId", torder.getOrderId());
        try {
            return joinPoint.proceed();
        } finally {
            MDC.remove("orderId");
        }
    }

    @Pointcut("(execution(* xxx.xxxx.xxx.web.controller.CommonController.commitJCInformation(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.impl.OrderServiceImpl.getAsyncErrorStatusOrder(..)) ||" +
            "execution(* xxx.xxxx.xxx.web.controller.CommonController.getStatusByOrderId(..)) ||" +
            "execution(* xxx.xxxx.xxx.web.controller.CommonController.userComment(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.impl.OrderServiceImpl.commitJCInformation(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.OrderConsumerService.getTextStatusByOrderId(..)) ||" +
            "execution(* xxx.xxxx.xxx.service.OrderConsumerService.getPaperStatusByOrderId(..)) ||" +
            "execution(* xxx.xxxx.xxx.manager.ThirdManager.getTaskProcessStatus(..)) ||" +
            "execution(* xxx.xxxx.xxx.manager.ThirdManager.getTextTaskProcessStatus(..)) ||" +
            "execution(* xxx.xxxx.xxx.manager.ThirdManager.createTextAlgorithmTask(..)))" +
            "&& args(orderId, ..)")
    public void orderMethod2(String orderId) {
    }

    @Around(value = "orderMethod2(orderId)", argNames = "joinPoint,orderId")
    public Object logMethod2(ProceedingJoinPoint joinPoint, String orderId) throws Throwable {
        log.info("Accessed method: {}", joinPoint.getSignature().toShortString());
        MDC.put("orderId", orderId);
        try {
            return joinPoint.proceed();
        } finally {
            MDC.remove("orderId");
        }
    }
}