前言

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

实现思路

  • 串联的核心在于要把ID作为一个请求必传参数,例如我们手动打印日志的时候,可以在日志中加上我们的业务ID,例如
    1
    log.info("提交订单开始:{}", orderId);
  • 但是此种方式较为繁琐,我们需要在每条日志中都手动加上orderId的输出,那么有没有更简单的方式呢?首先想到的是AOP,因为AOP可以将日志记录的行为从业务的核心逻辑中分离出来,而MDC是一个线程安全的存放诊断日志的容器,在处理请求前将请求的唯一标示放到MDC容器中,这个唯一标示会随着日志一起输出,以此来区分该条日志是属于那个请求的。并在请求处理完成之后清除MDC容器。
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    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的值。
    1
    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信息记录到日志中
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    @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的方法,所以会匹配错)。
  • 我这里的建议是通过方法名进行匹配,那么就需要订单相关的方法名的后缀进行统一,然后切点表达式按方法名后缀匹配就好了 (后期有空再重构重构代码吧,毕竟这里写的实在不太好)
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    @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");
    }
    }
    }