Categories
程式開發

【線上排查實戰】AOP切面執行順序你真的了解嗎


前言

忙,是我這個月的主旋律,也是我頻繁鴿文章的接口————蠻三刀把刀

公司這兩個月啟動了全新的項目,項目排期滿滿噹噹,不過該學習還是要學習。這不,給公司搭項目的時候,踩到了一個Spring AOP的坑。

本文內容重點:

問題描述Spring AOP執行順序探究順序錯誤的真相代碼驗證結論

本文閱讀大概需要:3分鐘

>

碼字不易,求個關注,歡迎關注我的個人原創公眾號:後端技術漫談(二維碼見文章底部)

問題描述

公司新項目需要搭建一個新的前後分離HTTP服務,我選擇了目前比較熟悉的SpringBoot Web來快速搭建一個可用的系統。

魯迅說過,不要隨便升級已經穩定使用的版本。我偏不信這個邪,仗著自己用了這麼久Spring,怎麼能不衝呢。不說了,直接引入了最新的SprinBoot 2.3.4.RELEASE版本,開始給項目搭架子。

起初,大多數的組件引入都一切順利,本以為就要大功告成了,沒想到在搭建日誌切面時栽了跟頭。

作為一個接口服務,為了方便查詢接口調用情況和定位問題,一般都會將請求日誌打印出來,而Spring的AOP作為切面支持,完美的切合了日誌記錄的需求。

之前的項目中,運行正確的切面日誌記錄效果如下圖:

【線上排查實戰】AOP切面執行順序你真的了解嗎 1

可以看到圖內的一次方法調用,會輸出請求url,出入參,以及請求IP等等,之前為了好看,還加入了分割線。

我把這個實現類放入新項目中,執行出來卻是這樣的:

【線上排查實戰】AOP切面執行順序你真的了解嗎 2

我揉了揉眼睛,仔細看了看複製過來的老代碼,精簡版如下:

/**
* 在切点之前织入
* @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執行順序的的資料,大多數時候,你會查到如下的答案:

正常情況

【線上排查實戰】AOP切面執行順序你真的了解嗎 3

異常情況

【線上排查實戰】AOP切面執行順序你真的了解嗎 4

多個切面的情況

【線上排查實戰】AOP切面執行順序你真的了解嗎 5

所以@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

【線上排查實戰】AOP切面執行順序你真的了解嗎 6

從Spring Framework 5.2.7開始,在相同@Aspect類中定義的,需要在相同連接點運行的通知方法將根據其建議類型按照從高到低的優先級從高到低的順序分配優先級:@Around,@Before ,@After,@AfterReturning,@AfterThrowing。

我粗淺的翻譯一下重點:

從Spring5.2.7開始,在相同@Aspect類中,通知方法將根據其類型按照從高到低的優先級進行執行:@Around,@Before ,@After,@AfterReturning,@AfterThrowing。

這樣看其實對比不明顯,我們再回到老版本,也就是2.2.5.RELEASE對應的spring-aop-5.2.4.RELEASE,當時的文檔是這麼寫的:

當多條建議都希望在同一連接點上運行時會發生什麼? Spring AOP遵循與AspectJ相同的優先級規則來確定建議執行的順序。 優先級最高的建議首先“在途中”運行(因此,給定兩條優先建議,則優先級最高的建議首先運行)。 從連接點“出路”中,優先級最高的建議將最後運行(因此,給定兩條後置通知,優先級最高的建議將第二次運行)。

簡單翻譯:在相同@Aspect類中Spring AOP遵循與AspectJ相同的優先級規則來確定advice執行的順序。

再挖深一點,那麼AspectJ的優先級規則是什麼樣的?

我找了AspectJ的文檔:

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

【線上排查實戰】AOP切面執行順序你真的了解嗎 7

在特定的連接點處,建議按優先級排序。一個環繞通知控制著是否通過調用procedure運行較低優先級的建議。 進行下去的調用將以下一個優先級運行建議,如果沒有其他建議,則在連接點下運行計算。一個先行建議可以通過引發異常來阻止運行優先級較低的建議。 但是,如果正常返回,則將運行下一個優先級的建議,或者如果沒有其他建議則在連接品脫下進行計算。返回建議後運行將運行下一個優先級的建議,或在連接下進行計算如果沒有其他建議,請指出。 然後,如果該計算正常返回,則該通知的主體將運行。在拋出建議後運行將運行下一個優先級的建議,如果沒有其他建議,則在連接點下運行該計算。 然後,如果該計算引發了適當類型的異常,則建議的主體將運行。在建議之後運行將運行下一個優先級的建議,如果沒有其他建議,則在連接點下運行該計算。 然後,建議的主體將運行。

大夥又要說了,哎呀太長不看!簡短地說,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;
}

我們將版本改為2.2.5.RELEASE,結果如圖:

【線上排查實戰】AOP切面執行順序你真的了解嗎 8

我們將版本改為2.3.4.RELEASE,結果如圖:

【線上排查實戰】AOP切面執行順序你真的了解嗎 9

結論

經過上面的資料文檔查閱,我能給出的結論是:

從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面試知識設計模式/數據結構/算法題解讀書筆記/逸聞趣事/程序人生

個人公眾號:後端技術漫談

【線上排查實戰】AOP切面執行順序你真的了解嗎 10

如果文章對你有幫助,不妨點贊,收藏起來~