SpringBoot 日志切面

Posted 2023-04-25 Qiyuanc

在 SpringBoot 里试一下面向切面编程（AOP）。

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 中，通知分为五类：

1. @Before 前置通知：在方法执行前（紧邻切入点，后面会说）执行；
2. @Around 环绕通知：方法执行前后都有通知，通知在方法前还是后取决于其中的 ProceedingJoinPoint.proceed() 的位置；
3. @AfterThrowing 异常通知：方法抛出异常之后通知；
4. @AfterReturnning 返回通知：方法成功执行之后通知；
5. @After 最终通知：也叫后置通知，但感觉最终通知合适一点，在方法执行后执行。

当它们五个一起使用时，执行顺序为：

1. 环绕通知的前置部分（ ProceedingJoinPoint.proceed() 之前的代码）；
2. 前置通知；
3. 目标方法；
4. 异常通知（如果出现异常）；
5. 返回通知（如果正常返回）；
6. 最终通知；
7. 环绕通知的异常部分（ try...catch 中的代码，如果出现异常 ）；
8. 环绕通知的后置部分（ 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);
    

说明一下其中的几个点：

1. @EnableAspectJAutoProxy 是一个 Spring 注解，用于启用基于注解的 Spring AOP 支持；此处只有一个切面类就写在上面了，不然一般写在配置类上比较好；
2. @Aspect 注解标记此类为一个切面类，Spring 才会将此类作为切面处理；
3. @PointCut 注解声明一个切入点，它下面的方法只是个皮套，这个注解写在方法上，使用通知注解时指定这个方法就可以了，相当于别名；不然就要在每个通知注解里指定切入点，很麻烦；
4. @Around 环绕通知里的 ProceedJoinPoint 参数可以控制方法的执行，只有环绕通知能用这个参数，其他的通知只能用 JoinPoint 类型的；
5. @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