问题描述

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

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

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

作为一个接口服务，为了方便查询接口调用情况和定位问题，一般都会将请求日志打印出来，而Spring的AOP作为切面支持，完美的切合了日志记录的需求。

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

可以看到图内的一次方法调用，会输出请求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

As of Spring Framework 5.2.7, advice methods defined in the same @Aspect class that need to run at the same join point are assigned precedence based on their advice type in the following order, from highest to lowest precedence: @Around, @Before, @After, @AfterReturning, @AfterThrowing.

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

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

What happens when multiple pieces of advice all want to run at the same join point? Spring AOP follows the same precedence rules as AspectJ to determine the order of advice execution. The highest precedence advice runs first “on the way in” (so, given two pieces of before advice, the one with highest precedence runs first). “On the way out” from a join point, the highest precedence advice runs last (so, given two pieces of after advice, the one with the highest precedence will run second).

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

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

我找了AspectJ的文档：

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

At a particular join point, advice is ordered by precedence.
A piece of around advice controls whether advice of lower precedence will run by calling proceed. The call to proceed will run the advice with next precedence, or the computation under the join point if there is no further advice.
A piece of before advice can prevent advice of lower precedence from running by throwing an exception. If it returns normally, however, then the advice of the next precedence, or the computation under the join pint if there is no further advice, will run.
Running after returning advice will run the advice of next precedence, or the computation under the join point if there is no further advice. Then, if that computation returned normally, the body of the advice will run.
Running after throwing advice will run the advice of next precedence, or the computation under the join point if there is no further advice. Then, if that computation threw an exception of an appropriate type, the body of the advice will run.
Running after advice will run the advice of next precedence, or the computation under the join point if there is no further advice. Then the body of the advice will run.

大伙又要说了，哎呀太长不看！简短地说，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;
    }