【线上排查实战】AOP切面执行顺序你真的了解吗

前言

公司这两个月启动了全新的项目，项目排期满满当当，不过该学习还是要学习。这不，给公司搭项目的时候，踩到了一个Spring AOP的坑。

本文内容重点：

• 问题描述
• Spring AOP执行顺序
• 探究顺序错误的真相
• 代码验证
• 结论

问题描述

公司新项目需要搭建一个新的前后分离HTTP服务，我选择了目前比较熟悉的SpringBoot Web来快速搭建一个可用的系统。

鲁迅说过，不要随便升级已经稳定使用的版本。我偏不信这个邪，仗着自己用了这么久Spring，怎么能不冲呢。不说了，直接引入了最新的SprinBoot 2.3.4.RELEASE版本，开始给项目搭架子。

起初，大多数的组件引入都一切顺利，本以为就要大功告成了，没想到在搭建日志切面时栽了跟头。

之前的项目中，运行正确的切面日志记录效果如下图：

可以看到图内的一次方法调用，会输出请求url，出入参，以及请求IP等等，之前为了好看，还加入了分割线。

我把这个实现类放入新项目中，执行出来却是这样的：

我揉了揉眼睛，仔细看了看复制过来的老代码，精简版如下：

/**
 * 在切点之前织入
 * @param joinPoint
 * @throws Throwable
 */
@Before("webLog()")
public void doBefore(JoinPoint joinPoint) throws Throwable {
    // 开始打印请求日志
    ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
    HttpServletRequest request = attributes.getRequest();

    // 初始化traceId
    initTraceId(request);

    // 打印请求相关参数
    LOGGER.info("========================================== Start ==========================================");
    // 打印请求 url
    LOGGER.info("URL            : {}", request.getRequestURL().toString());
    // 打印 Http method
    LOGGER.info("HTTP Method    : {}", request.getMethod());
    // 打印调用 controller 的全路径以及执行方法
    LOGGER.info("Class Method   : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
    // 打印请求的 IP
    LOGGER.info("IP             : {}", IPAddressUtil.getIpAdrress(request));
    // 打印请求入参
    LOGGER.info("Request Args   : {}", joinPoint.getArgs());
}

/**
 * 在切点之后织入
 * @throws Throwable
 */
@After("webLog()")
public void doAfter() throws Throwable {
    LOGGER.info("=========================================== End ===========================================");
}

/**
 * 环绕
 * @param proceedingJoinPoint
 * @return
 * @throws Throwable
 */
@Around("webLog()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
    long startTime = System.currentTimeMillis();
    Object result = proceedingJoinPoint.proceed();
    // 打印出参
    LOGGER.info("Response Args  : {}", result);
    // 执行耗时
    LOGGER.info("Time-Consuming : {} ms", System.currentTimeMillis() - startTime);
    return result;
}

代码感觉完全没有问题，难道新版本的SpringBoot出Bug了。

显然，成熟的框架不会在这种大方向上犯错误，那会不会是新版本的SpringBoot把@After和@Around的顺序反过来了？

其实事情也没有那么简单。

Spring AOP执行顺序

我们先来回顾下Spring AOP执行顺序。

我们在网上查找关于SpringAop执行顺序的的资料，大多数时候，你会查到如下的答案：

正常情况

异常情况

多个切面的情况

所以@Around理应在@After之前，但是在SprinBoot 2.3.4.RELEASE版本中，@Around切切实实执行在了@After之后。

当我尝试切换回2.2.5.RELEASE版本后，执行顺序又回到了@Around-->@After

探究顺序错误的真相

既然知道了是SpringBoot版本升级导致的问题（或者说顺序变化），那么就要来看看究竟是哪个库对AOP执行的顺序进行了变动，毕竟，SpringBoot只是“形”，真正的内核在Spring。

我们打开pom.xml文件，使用插件查看spring-aop的版本，发现SpringBoot 2.3.4.RELEASE 版本使用的AOP是spring-aop-5.2.9.RELEASE。

而2.2.5.RELEASE对应的是spring-aop-5.2.4.RELEASE

于是我去官网搜索文档，不得不说Spring由于过于庞大，官网的文档已经到了冗杂的地步，不过最终还是找到了：

https://docs.spring.io/spring-framework/docs/5.2.9.RELEASE/spring-framework-reference/core.html#aop-ataspectj-advice-ordering

我粗浅的翻译一下重点：

从Spring5.2.7开始，在相同@Aspect类中，通知方法将根据其类型按照从高到低的优先级进行执行：@Around，@Before ，@After，@AfterReturning，@AfterThrowing。

这样看其实对比不明显，我们再回到老版本，也就是2.2.5.RELEASE对应的spring-aop-5.2.4.RELEASE，当时的文档是这么写的：

简单翻译：在相同@Aspect类中Spring AOP遵循与AspectJ相同的优先级规则来确定advice执行的顺序。

再挖深一点，那么AspectJ的优先级规则是什么样的？

我找了AspectJ的文档：

https://www.eclipse.org/aspectj/doc/next/progguide/semantics-advice.html

大伙又要说了，哎呀太长不看！简短地说，Aspectj的规则就是上面我们能够在网上查阅到的顺序图展示的那样，依旧是老的顺序。

代码验证

我把业务逻辑从代码中删除，只验证下这几个advice的执行顺序：

package com.bj58.xfbusiness.cloudstore.system.aop;

import com.bj58.xfbusiness.cloudstore.utils.IPAddressUtil;
import com.bj58.xfbusiness.cloudstore.utils.TraceIdUtil;
import org.apache.commons.lang3.StringUtils;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;

/**
 * 日志切面
 */
@Aspect
@Component
public class WebLogAspect {

    private final static Logger LOGGER = LoggerFactory.getLogger(WebLogAspect.class);

    /** 以 controller 包下定义的所有请求为切入点 */
    @Pointcut("execution(public * com.xx.xxx.xxx.controller..*.*(..))")
    public void webLog() {}

    /**
     * 在切点之前织入
     * @param joinPoint
     * @throws Throwable
     */
    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) throws Throwable {
        LOGGER.info("-------------doBefore-------------");
    }

    @AfterReturning("webLog()")
    public void afterReturning() {
        LOGGER.info("-------------afterReturning-------------");
    }
    @AfterThrowing("webLog()")
    public void afterThrowing() {
        LOGGER.info("-------------afterThrowing-------------");
    }

    /**
     * 在切点之后织入
     * @throws Throwable
     */
    @After("webLog()")
    public void doAfter() throws Throwable {
        LOGGER.info("-------------doAfter-------------");
    }

    /**
     * 环绕
     * @param proceedingJoinPoint
     * @return
     * @throws Throwable
     */
    @Around("webLog()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        LOGGER.info("-------------doAround before proceed-------------");
        Object result = proceedingJoinPoint.proceed();
        LOGGER.info("-------------doAround after proceed-------------");
        return result;
    }

我们将版本改为，结果如图：

我们将版本改为，结果如图：

结论

经过上面的资料文档查阅，我能给出的结论是：

从Spring5.2.7开始，Spring AOP不再严格按照AspectJ定义的规则来执行advice，而是根据其类型按照从高到低的优先级进行执行：@Around，@Before ，@After，@AfterReturning，@AfterThrowing。

这次的研究思考十分仓促，如果结论有误请大家踊跃指正，也欢迎大家自己尝试，毕竟口说无凭，实验室检验真理的唯一标准！

参考

https://www.cnblogs.com/dennyLee2025/p/13724981.html

https://segmentfault.com/a/1190000011283029

关注我

我是一名后端开发工程师。主要关注后端开发，数据安全，边缘计算等方向，欢迎交流。

各大平台都可以找到我

• 微信公众号：后端技术漫谈
• Github：@qqxx6661
• CSDN：@蛮三刀把刀
• 知乎：@后端技术漫谈
• 掘金：@蛮三刀把刀
• 腾讯云+社区：@后端技术漫谈

原创文章主要内容

• 后端开发实战
• Java面试知识
• 设计模式/数据结构/算法题解
• 读书笔记/逸闻趣事/程序人生

个人公众号：后端技术漫谈

如果文章对你有帮助，不妨点赞，收藏起来~