SpringBoot 日志切面
Posted Qiyuanc
tags:
篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了SpringBoot 日志切面相关的知识,希望对你有一定的参考价值。
SpringBoot 日志切面
在 SpringBoot 中搞一下 AOP 切面,复习一下。太详细的概念就不用说了,直接看 Spring AOP实现 吧,当时写的除了有点模糊也没什么大问题。
AOP 概念
在 SpringBoot 中使用 AOP,直接引入 spring-boot-starter-aop
的包即可:
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
<version>2.2.13.RELEASE</version>
</dependency>
再说一下几个关键概念,涉及到 AOP 注解的使用:
- 横切关注点 :跨越程序多个模块的方法或功能。即与业务逻辑无关,但我们也要关注的部分,就是横切关注点。如日志、安全、缓存等。
- 切面( Aspect ) :将横切关注点模块化得到的特殊对象,即切面应是一个类,表现为 AOP 在哪干和干什么的集合。
- 连接点( JoinPoint ) :应用执行过程中能够插入切面的一个点,这个点可以是方法执行、方法调用、处理异常等,表现为 AOP 在哪干。
- 切入点( PointCut ) :切面通知执行的地点,即要插入增强处理的连接点,表现为 AOP 在哪干的集合。
- 通知( Advice) :切面要完成的增强处理,通知描述了切面何时执行以及如何执行增强处理,即通知应是切面中的方法,表现为 AOP 干什么。
在 Spring 中,通知分为五类:
- @Before 前置通知:在方法执行前(紧邻切入点,后面会说)执行;
- @Around 环绕通知:方法执行前后都有通知,通知在方法前还是后取决于其中的
ProceedingJoinPoint.proceed()
的位置; - @AfterThrowing 异常通知:方法抛出异常之后通知;
- @AfterReturnning 返回通知:方法成功执行之后通知;
- @After 最终通知:也叫后置通知,但感觉最终通知合适一点,在方法执行后执行。
当它们五个一起使用时,执行顺序为:
- 环绕通知的前置部分(
ProceedingJoinPoint.proceed()
之前的代码); - 前置通知;
- 目标方法;
- 异常通知(如果出现异常);
- 返回通知(如果正常返回);
- 最终通知;
- 环绕通知的异常部分(
try...catch
中的代码,如果出现异常 ); - 环绕通知的后置部分(
ProceedingJoinPoint.proceed()
之后的代码,如果正常返回)。
这个顺序时因为环绕通知的 ProceedingJoinPointproceed()
方法导致的,只有环绕通知可以使用 ProceedingJoinPoint
,它是一个特殊的连接点 JoinPoint
参数,除了可以获取连接点的信息外,还能控制方法的执行。
日志切面
先放上完整代码:
@EnableAspectJAutoProxy
@Component
@Aspect
@Slf4j
public class LogAspect
@Pointcut("execution(* org.qiyuanc.service.*.*(..))")
private void pointCut()
// Just a pointcut
@Before("pointCut()")
public void doBefore(JoinPoint jp)
String className = jp.getTarget().getClass().getSimpleName();
String methodName = jp.getSignature().getName();
log.info("==========前置通知 . 参数 ==========", className, methodName, jp.getArgs());
@Around("pointCut()")
public Object doAround(ProceedingJoinPoint pjp) throws Throwable
String className = pjp.getTarget().getClass().getSimpleName();
String methodName = pjp.getSignature().getName();
// 记录进入
log.info("==========环绕通知 进入方法 . ==========", className, methodName);
Object result = null;
try
result = pjp.proceed();
catch (Throwable throwable)
// 记录异常,重新抛出,异常不应该在这里被吞没
log.error("==========环绕通知 出现异常 . : ==========", className, methodName, throwable.getMessage());
throw throwable;
// 记录退出
log.info("==========环绕通知 退出方法 . ==========", className, methodName);
return result;
@AfterReturning(pointcut = "pointCut()", returning = "result")
public void doAfterReturning(JoinPoint jp, Object result)
String className = jp.getTarget().getClass().getSimpleName();
String methodName = jp.getSignature().getName();
log.info("==========返回通知 . 返回值 ==========", className, methodName, result);
@AfterThrowing(pointcut = "pointCut()", throwing = "ex")
public void doAfterThrowing(JoinPoint jp, Exception ex)
String className = jp.getTarget().getClass().getSimpleName();
String methodName = jp.getSignature().getName();
log.info("==========异常通知 . 异常 ==========", className, methodName, ex.getMessage());
@After("pointCut()")
public void doAfter(JoinPoint jp)
String className = jp.getTarget().getClass().getSimpleName();
String methodName = jp.getSignature().getName();
log.info("==========最终通知 . ==========", className, methodName);
说明一下其中的几个点:
@EnableAspectJAutoProxy
是一个 Spring 注解,用于启用基于注解的 Spring AOP 支持;此处只有一个切面类就写在上面了,不然一般写在配置类上比较好;@Aspect
注解标记此类为一个切面类,Spring 才会将此类作为切面处理;@PointCut
注解声明一个切入点,它下面的方法只是个皮套,这个注解写在方法上,使用通知注解时指定这个方法就可以了,相当于别名;不然就要在每个通知注解里指定切入点,很麻烦;@Around
环绕通知里的ProceedJoinPoint
参数可以控制方法的执行,只有环绕通知能用这个参数,其他的通知只能用JoinPoint
类型的;@AfterReturning
使用到了返回值参数,需要在注解中绑定,@AfterThrowing
同理。
最后附上执行时的日志,正常执行时:
2023-04-25 11:05:42.287 INFO 15752 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========环绕通知 进入方法 TestService.DataListRead ==========
2023-04-25 11:05:42.288 INFO 15752 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========前置通知 TestService.DataListRead 参数 [java.io.FileInputStream@22ddb664, test.xlsx] ==========
2023-04-25 11:05:42.537 INFO 15752 --- [nio-8080-exec-1] org.qiyuanc.service.TestService:
==========TestService 读取数据==========
2023-04-25 11:05:42.537 INFO 15752 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========返回通知 TestService.DataListRead 返回值 [TestEntity(A=1A, B=1B, C=1C, D=1D, F=1E)] ==========
2023-04-25 11:05:42.537 INFO 15752 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========最终通知 TestService.DataListRead ==========
2023-04-25 11:05:42.537 INFO 15752 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========环绕通知 退出方法 TestService.DataListRead ==========
出现异常时:
2023-04-25 10:58:27.329 INFO 19208 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========环绕通知 进入方法 TestService.DataListRead ==========
2023-04-25 10:58:27.329 INFO 19208 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========前置通知 TestService.DataListRead 参数 [java.io.FileInputStream@50548568, test.xlsx] ==========
2023-04-25 10:58:27.581 INFO 19208 --- [nio-8080-exec-1] org.qiyuanc.service.TestService:
==========TestService 读取数据==========
2023-04-25 10:58:27.581 INFO 19208 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========异常通知 TestService.DataListRead 异常 测试 ==========
2023-04-25 10:58:27.581 INFO 19208 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========最终通知 TestService.DataListRead ==========
2023-04-25 10:58:27.581 ERROR 19208 --- [nio-8080-exec-1] org.qiyuanc.aspect.LogAspect:
==========环绕通知 出现异常 TestService.DataListRead : 测试 ==========
使用起来还是很简单的。
springboot配置aop切面日志打印
一、SpringBoot Aop说明
1. Aop
AOP(Aspect-Oriented Programming,面向切面编程),它利用一种”横切”的技术,将那些多个类的共同行为封装到一个可重用的模块。便于减少系统的重复代码,降低模块之间的耦合度,并有利于未来的可操作性和可维护性。
2. AOP相关概念:
Aspect(切面):声明类似于Java中的类声明,在Aspect中会包含一些Pointcut及相应的Advice。
Joint point(连接点):表示在程序中明确定义的点。包括方法的调用、对类成员的访问等。
Pointcut(切入点):表示一个组Joint point,如方法名、参数类型、返回类型等等。
Advice(通知):Advice定义了在Pointcut里面定义的程序点具体要做的操作,它通过(before、around、after(return、throw)、finally来区别实在每个Joint point之前、之后还是执行 前后要调用的代码。
Before:在执行方法前调用Advice,比如请求接口之前的登录验证。
Around:在执行方法前后调用Advice,这是最常用的方法。
After:在执行方法后调用Advice,after、return是方法正常返回后调用,after hrow是方法抛出异常后调用。
Finally:方法调用后执行Advice,无论是否抛出异常还是正常返回。
AOP proxy:AOP proxy也是Java对象,是由AOP框架创建,用来完成上述动作,AOP对象通常可以通过JDK dynamic proxy完成,或者使用CGLIb完成。
Weaving:实现上述切面编程的代码织入,可以在编译时刻,也可以在运行时刻,Spring和其它大多数Java框架都是在运行时刻生成代理。
二、代码示例
1. POM引入
<dependencies> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-web</artifactId> </dependency> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-aop</artifactId> </dependency> <!-- 分析客户端信息的工具类--> <dependency> <groupId>eu.bitwalker</groupId> <artifactId>UserAgentUtils</artifactId> <version>1.21</version> </dependency> <!-- lombok --> <dependency> <groupId>org.projectlombok</groupId> <artifactId>lombok</artifactId> <scope>1.18.10</scope> </dependency> </dependencies>
2、切面:WebLogAspect代码
/** * 添加aop日志打印 * * @author 马振全 2020/1/13 14:42 */ @Aspect @Component @Slf4j public class WebLogAspect { /** * 进入方法时间戳 */ private Long startTime; /** * 方法结束时间戳(计时) */ private Long endTime; public WebLogAspect() { } /** * 定义请求日志切入点,其切入点表达式有多种匹配方式,这里是指定路径 */ @Pointcut("execution(public * com.soyoung.ad.engine.controller.*.*(..))") public void webLogPointcut() { } /** * 前置通知: * 1. 在执行目标方法之前执行,比如请求接口之前的登录验证; * 2. 在前置通知中设置请求日志信息,如开始时间,请求参数,注解内容等 * * @param joinPoint * @throws Throwable */ @Before("webLogPointcut()") public void doBefore(JoinPoint joinPoint) { // 接收到请求,记录请求内容 ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes(); HttpServletRequest request = attributes.getRequest(); //获取请求头中的User-Agent UserAgent userAgent = UserAgent.parseUserAgentString(request.getHeader("User-Agent")); //打印请求的内容 startTime = System.currentTimeMillis(); log.info("请求开始时间:{}", LocalDateTime.now()); log.info("请求Url : {}", request.getRequestURL().toString()); log.info("请求方式 : {}", request.getMethod()); log.info("请求ip : {}", request.getRemoteAddr()); log.info("请求方法 : ", joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName()); log.info("请求参数 : {}", Arrays.toString(joinPoint.getArgs())); // 系统信息 log.info("浏览器:{}", userAgent.getBrowser().toString()); log.info("浏览器版本:{}", userAgent.getBrowserVersion()); log.info("操作系统: {}", userAgent.getOperatingSystem().toString()); } /** * 返回通知: * 1. 在目标方法正常结束之后执行 * 1. 在返回通知中补充请求日志信息,如返回时间,方法耗时,返回值,并且保存日志信息 * * @param ret * @throws Throwable */ @AfterReturning(returning = "ret", pointcut = "webLogPointcut()") public void doAfterReturning(Object ret) throws Throwable { endTime = System.currentTimeMillis(); log.info("请求结束时间:{}", LocalDateTime.now()); log.info("请求耗时:{}", (endTime - startTime)); // 处理完请求,返回内容 log.info("请求返回 : {}", ret); } /** * 异常通知: * 1. 在目标方法非正常结束,发生异常或者抛出异常时执行 * 1. 在异常通知中设置异常信息,并将其保存 * * @param throwable */ @AfterThrowing(value = "webLogPointcut()", throwing = "throwable") public void doAfterThrowing(Throwable throwable) { // 保存异常日志记录 log.error("发生异常时间:{}", LocalDateTime.now()); log.error("抛出异常:{}", throwable.getMessage()); } }
3、@Before和@AfterReturning部分也可使用以下代码替代
/** * 在执行方法前后调用Advice,这是最常用的方法,相当于@Before和@AfterReturning全部做的事儿 * @param pjp * @return * @throws Throwable */ @Around("webLogPointcut()") public Object doAround(ProceedingJoinPoint pjp) throws Throwable { // 接收到请求,记录请求内容 ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes(); HttpServletRequest request = attributes.getRequest(); //获取请求头中的User-Agent UserAgent userAgent = UserAgent.parseUserAgentString(request.getHeader("User-Agent")); //打印请求的内容 startTime = System.currentTimeMillis(); log.info("请求Url : {}" , request.getRequestURL().toString()); log.info("请求方式 : {}" , request.getMethod()); log.info("请求ip : {}" , request.getRemoteAddr()); log.info("请求方法 : " , pjp.getSignature().getDeclaringTypeName() , "." , pjp.getSignature().getName()); log.info("请求参数 : {}" , Arrays.toString(pjp.getArgs())); // 系统信息 log.info("浏览器:{}", userAgent.getBrowser().toString()); log.info("浏览器版本:{}",userAgent.getBrowserVersion()); log.info("操作系统: {}", userAgent.getOperatingSystem().toString()); // pjp.proceed():当我们执行完切面代码之后,还有继续处理业务相关的代码。proceed()方法会继续执行业务代码,并且其返回值,就是业务处理完成之后的返回值。 Object ret = pjp.proceed(); log.info("请求结束时间:"+ LocalDateTime.now()); log.info("请求耗时:{}" , (System.currentTimeMillis() - startTime)); // 处理完请求,返回内容 log.info("请求返回 : " , ret); return ret; }
4、测试结果
2020-01-13 15:18:21.309 INFO xxx.WebLogAspect : 请求开始时间:2020-01-13T15:18:21.309
2020-01-13 15:18:21.309 INFO xxx.WebLogAspect : 请求Url : http://localhost:8020/api/v1/hourlyStat/findHourlyStatReportList
2020-01-13 15:18:21.320 INFO xxx.WebLogAspect : 请求方式 : POST
2020-01-13 15:18:21.321 INFO xxx.WebLogAspect : 请求ip : 0:0:0:0:0:0:0:1
2020-01-13 15:18:21.322 INFO xxx.WebLogAspect : 请求方法 :
2020-01-13 15:18:21.325 INFO xxx.WebLogAspect : 请求参数 : [HourlyStat{subStrategyId=null}]
2020-01-13 15:18:21.326 INFO xxx.WebLogAspect : 浏览器:CHROME
2020-01-13 15:18:21.327 INFO xxx.WebLogAspect : 浏览器版本:78.0.3904.108
2020-01-13 15:18:21.333 INFO xxx.WebLogAspect : 操作系统: WINDOWS_10
2020-01-13 15:18:21.403 INFO xxx.WebLogAspect : 请求结束时间:2020-01-13T15:18:21.403
2020-01-13 15:18:21.405 INFO xxx.WebLogAspect : 请求耗时:94
2020-01-13 15:18:21.405 INFO xxx.WebLogAspect : 请求返回 : com.soyoung.ad.engine.common.Result@2f935d03
2020-01-13 15:18:21.492 INFO xxx.WebLogAspect : 请求结束时间:2020-01-13T15:18:21.492
2020-01-13 15:18:21.493 INFO xxx.WebLogAspect : 请求耗时:183
2020-01-13 15:18:21.494 INFO xxx.WebLogAspect : 请求返回 : com.soyoung.ad.engine.common.Result@7199e922
2020-01-13 15:18:42.859 INFO xxx.WebLogAspect : 请求开始时间:2020-01-13T15:18:42.859
2020-01-13 15:18:42.860 INFO xxx.WebLogAspect : 请求Url : http://localhost:8020/api/v1/hourlyStat/findHourlyStatReportList
2020-01-13 15:18:42.860 INFO xxx.WebLogAspect : 请求方式 : POST
2020-01-13 15:18:42.861 INFO xxx.WebLogAspect : 请求ip : 0:0:0:0:0:0:0:1
2020-01-13 15:18:42.861 INFO xxx.WebLogAspect : 请求方法 :
2020-01-13 15:18:42.862 INFO xxx.WebLogAspect : 请求参数 : [HourlyStat{subStrategyId=1003}]
2020-01-13 15:18:42.862 INFO xxx.WebLogAspect : 浏览器:CHROME
2020-01-13 15:18:42.863 INFO xxx.WebLogAspect : 浏览器版本:78.0.3904.108
2020-01-13 15:18:42.864 INFO xxx.WebLogAspect : 操作系统: WINDOWS_10
2020-01-13 15:18:42.909 INFO xxx.WebLogAspect : 请求结束时间:2020-01-13T15:18:42.909
2020-01-13 15:18:42.910 INFO xxx.WebLogAspect : 请求耗时:50
2020-01-13 15:18:42.910 INFO xxx.WebLogAspect : 请求返回 : com.soyoung.ad.engine.common.Result@7d494cbd
以上是关于SpringBoot 日志切面的主要内容,如果未能解决你的问题,请参考以下文章