Spring AOP @After,@Around,@Before执行的顺序以及可能遇到的问题

淩亂°似流年 2022-12-24 03:59 183阅读 0赞

AOP中有@Before，@After，@Around，@AfterRunning注解等等。

首先上下自己的代码，定义了切点的定义

1.  `@Aspect`
2.  `@Component`
3.  `public class LogApsect {`
4.   
5.  `private static final Logger logger = LoggerFactory.getLogger(LogApsect.class);`
6.   
7.  `ThreadLocal<Long> startTime = new ThreadLocal<>();`
8.   
9.  `// 第一个*代表返回类型不限`
10. `// 第二个*代表所有类`
11. `// 第三个*代表所有方法`
12. `// (..) 代表参数不限`
13. `@Pointcut("execution(public * com.lmx.blog.controller.*.*(..))")`
14. `@Order(2)`
15. `public void pointCut(){};`
16.  
17. `@Pointcut("@annotation(com.lmx.blog.annotation.RedisCache)")`
18. `@Order(1) // Order 代表优先级，数字越小优先级越高`
19. `public void annoationPoint(){};`
20.  
21. `@Before(value = "annoationPoint() || pointCut()")`
22. `public void before(JoinPoint joinPoint){`
23. `System.out.println("方法执行前执行......before");`
24. `ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();`
25. `HttpServletRequest request = attributes.getRequest();`
26. `logger.info("<=====================================================");`
27. `logger.info("请求来源： =》" + request.getRemoteAddr());`
28. `logger.info("请求URL：" + request.getRequestURL().toString());`
29. `logger.info("请求方式：" + request.getMethod());`
30. `logger.info("响应方法：" + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());`
31. `logger.info("请求参数：" + Arrays.toString(joinPoint.getArgs()));`
32. `logger.info("------------------------------------------------------");`
33. `startTime.set(System.currentTimeMillis());`
34. `}`
35.  
36. `// 定义需要匹配的切点表达式，同时需要匹配参数`
37. `@Around("pointCut() && args(arg)")`
38. `public Response around(ProceedingJoinPoint pjp,String arg) throws Throwable{`
39. `System.out.println("name:" + arg);`
40. `System.out.println("方法环绕start...around");`
41. `String result = null;`
42. `try{`
43. `result = pjp.proceed().toString() + "aop String";`
44. `System.out.println(result);`
45. `}catch (Throwable e){`
46. `e.printStackTrace();`
47. `}`
48. `System.out.println("方法环绕end...around");`
49. `return (Response) pjp.proceed();`
50. `}`
51.  
52. `@After("within(com.lmx.blog.controller.*Controller)")`
53. `public void after(){`
54. `System.out.println("方法之后执行...after.");`
55. `}`
56.  
57. `@AfterReturning(pointcut="pointCut()",returning = "rst")`
58. `public void afterRunning(Response rst){`
59. `if(startTime.get() == null){`
60. `startTime.set(System.currentTimeMillis());`
61. `}`
62. `System.out.println("方法执行完执行...afterRunning");`
63. `logger.info("耗时（毫秒）：" + (System.currentTimeMillis() - startTime.get()));`
64. `logger.info("返回数据：{}", rst);`
65. `logger.info("==========================================>");`
66. `}`
67.  
68. `@AfterThrowing("within(com.lmx.blog.controller.*Controller)")`
69. `public void afterThrowing(){`
70. `System.out.println("异常出现之后...afterThrowing");`
71. `}`
72.  
73.  
74. `}`

@Before，@After，@Around注解的区别大家可以自行百度下。总之就是@Around可以实现@Before和@After的功能，并且只需要在一个方法中就可以实现。

首先我们来测试一个方法用于获取数据库一条记录的

1.  `@RequestMapping("/achieve")`
2.  `public Response achieve(){`
3.  `System.out.println("方法执行-----------");`
4.  `return Response.ok(articleDetailSercice.getPrimaryKeyById(1L));`
5.  `}`

以下是控制台打印的日志

1.  `方法执行前执行......before`
2.  `2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - <=====================================================`
3.  `2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - 请求来源： =》0:0:0:0:0:0:0:1`
4.  `2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - 请求URL：http://localhost:8888/user/achieve`
5.  `2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - 请求方式：GET`
6.  `2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - 响应方法：com.lmx.blog.controller.UserController.achieve`
7.  `2018-11-23 16:31:59.796 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - 请求参数：[]`
8.  `2018-11-23 16:31:59.796 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - ------------------------------------------------------`
9.  `方法执行-----------`
10. `2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==> Preparing: select * from article_detail where id = ?`
11. `2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==> Preparing: select * from article_detail where id = ?`
12. `2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==> Parameters: 1(Long)`
13. `2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==> Parameters: 1(Long)`
14. `2018-11-23 16:31:59.814 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - <== Total: 1`
15. `2018-11-23 16:31:59.814 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - <== Total: 1`
16. `方法之后执行...after.`
17. `方法执行完执行...afterRunning`
18. `2018-11-23 16:31:59.824 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - 耗时（毫秒）：27`
19. `2018-11-23 16:31:59.824 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - 返回数据：com.lmx.blog.common.Response@8675ce5`
20. `2018-11-23 16:31:59.824 [http-nio-8888-exec-9] INFO c.l.blog.config.LogApsect - ==========================================>`

可以看到，因为没有匹配@Around的规则，所以没有进行环绕通知。（PS：我定义的环绕通知意思是要符合是 controller 包下的方法并且方法必须带有参数，而上述方法没有参数，所以只走了@before和@after方法，不符合@Around的匹配逻辑）

我们再试一下另一个带有参数的方法

1.  `@RedisCache(type = Response.class)`
2.  `@RequestMapping("/sendEmail")`
3.  `public Response sendEmailToAuthor(String content){`
4.  `System.out.println("测试执行次数");`
5.  `return Response.ok(true);`
6.  `}`

以下是该部分代码的console打印

1.  `name:第二封邮件呢`
2.  `方法环绕start...around`
3.  `方法执行前执行......before`
4.  `2018-11-23 16:34:55.347 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - <=====================================================`
5.  `2018-11-23 16:34:55.347 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求来源： =》0:0:0:0:0:0:0:1`
6.  `2018-11-23 16:34:55.347 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求URL：http://localhost:8888/user/sendEmail`
7.  `2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求方式：GET`
8.  `2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 响应方法：com.lmx.blog.controller.UserController.sendEmailToAuthor`
9.  `2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求参数：[第二封邮件呢]`
10. `2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - ------------------------------------------------------`
11. `测试执行次数`
12. `com.lmx.blog.common.Response@6d17f2fdaop String`
13. `方法环绕end...around`
14. `方法执行前执行......before`
15. `2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - <=====================================================`
16. `2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求来源： =》0:0:0:0:0:0:0:1`
17. `2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求URL：http://localhost:8888/user/sendEmail`
18. `2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求方式：GET`
19. `2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 响应方法：com.lmx.blog.controller.UserController.sendEmailToAuthor`
20. `2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 请求参数：[第二封邮件呢]`
21. `2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - ------------------------------------------------------`
22. `测试执行次数`
23. `方法之后执行...after.`
24. `方法执行完执行...afterRunning`
25. `2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 耗时（毫秒）：0`
26. `2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - 返回数据：com.lmx.blog.common.Response@79f85428`
27. `2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO c.l.blog.config.LogApsect - ==========================================>`

显而易见，该方法符合 @Around 环绕通知的匹配规则，所以进入了@Around的逻辑，但是发现了问题，所有的方法都被执行了2次，不管是切面层还是方法层。（有人估计要问我不是用的自定义注解 @RedisCache(type = Response.class) 么。为什么会符合 @Around的匹配规则呢，这个等会在下面说）

我们分析日志的打印顺序可以得出，在执行环绕方法时候，会优先进入 @Around下的方法。@Around的方法再贴一下代码。

1.  `// 定义需要匹配的切点表达式，同时需要匹配参数`
2.  `@Around("pointCut() && args(arg)")`
3.  `public Response around(ProceedingJoinPoint pjp,String arg) throws Throwable{`
4.  `System.out.println("name:" + arg);`
5.  `System.out.println("方法环绕start...around");`
6.  `String result = null;`
7.  `try{`
8.  `result = pjp.proceed().toString() + "aop String";`
9.  `System.out.println(result);`
10. `}catch (Throwable e){`
11. `e.printStackTrace();`
12. `}`
13. `System.out.println("方法环绕end...around");`
14. `return (Response) pjp.proceed();`
15. `}`

打印了前两行代码以后，转而去执行了 @Before方法，是因为中途触发了  ProceedingJoinPoint.proceed() 方法。这个方法的作用是执行被代理的方法，也就是说执行了这个方法之后会执行我们controller的方法，而后执行 @before，@after，然后回到@Around执行未执行的方法，最后执行 @afterRunning，如果有异常抛出能执行 @AfterThrowing

也就是说环绕的执行顺序是    @Around→@Before→@After→@Around执行 ProceedingJoinPoint.proceed() 之后的操作→@AfterRunning(如果有异常→@AfterThrowing)

而我们上述的日志相当于把上述结果执行了2遍，根本原因在于 ProceedingJoinPoint.proceed() 这个方法，可以发现在@Around 方法中我们使用了2次这个方法，然而每次调用这个方法时都会走一次@Before→@After→@Around执行 ProceedingJoinPoint.proceed() 之后的操作→@AfterRunning(如果有异常→@AfterThrowing)。因此问题是出现在这里。所以更改@Around部分的代码即可解决该问题。更改之后的代码如下：

1.  `@Around("pointCut() && args(arg)")`
2.  `public Response around(ProceedingJoinPoint pjp,String arg) throws Throwable{`
3.  `System.out.println("name:" + arg);`
4.  `System.out.println("方法环绕start...around");`
5.  `String result = null;`
6.  `Object object = pjp.proceed();`
7.  `try{`
8.  `result = object.toString() + "aop String";`
9.  `System.out.println(result);`
10. `}catch (Throwable e){`
11. `e.printStackTrace();`
12. `}`
13. `System.out.println("方法环绕end...around");`
14. `return (Response) object;`
15. `}`

更改代码之后的运行结果

1.  `name:第二封邮件呢`
2.  `方法环绕start...around`
3.  `方法执行前执行......before`
4.  `2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - <=====================================================`
5.  `2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - 请求来源： =》0:0:0:0:0:0:0:1`
6.  `2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - 请求URL：http://localhost:8888/user/sendEmail`
7.  `2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - 请求方式：GET`
8.  `2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - 响应方法：com.lmx.blog.controller.UserController.sendEmailToAuthor`
9.  `2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - 请求参数：[第二封邮件呢]`
10. `2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - ------------------------------------------------------`
11. `测试执行次数`
12. `com.lmx.blog.common.Response@1b1c76afaop String`
13. `方法环绕end...around`
14. `方法之后执行...after.`
15. `方法执行完执行...afterRunning`
16. `2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - 耗时（毫秒）：0`
17. `2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - 返回数据：com.lmx.blog.common.Response@1b1c76af`
18. `2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO c.l.blog.config.LogApsect - ==========================================>`

回到上述未解决的问题，为什么我定义了切面的另一个注解还可以进入@Around方法呢？

因为我们的方法仍然在controller下，因此满足该需求，如果我们定义了controller包下的某个controller才有用。例如：

@Pointcut("execution(public * com.lmx.blog.controller.UserController.*(..))")

而如果我们刚才定义的方法是写在 TestController 之下的，那么就不符合 @Around方法的匹配规则了，也不符合@before和@after的注解规则，因此不会匹配任何一个规则，如果需要匹配特定的方法，可以用自定义的注解形式或者特性controller下的方法

①：特性的注解形式

1.  `@Pointcut("@annotation(com.lmx.blog.annotation.RedisCache)")`
2.  `@Order(1) // Order 代表优先级，数字越小优先级越高`
3.  `public void annoationPoint(){};`

然后在所需要的方法上加入 @RedisCache注解，在@Before，@After，@Around等方法上添加该切点的方法名（“annoationPoint()”），如果有多个注解需要匹配则用 || 隔开

②：指定controller或者指定controller下的方法

1.  `@Pointcut("execution(public * com.lmx.blog.controller.UserController.*(..))")`
2.  `@Order(2)`
3.  `public void pointCut(){};`

该部分代码是指定了 com.lmx.blog.controller包下的UserController下的所有方法。

第一个\*代表的是返回类型不限

第二个\*代表的是该controller下的所有方法，