在 SpringBoot 中用 SpringAOP 实现日志记录功能

AOP为Aspect Oriented Programming的缩写,意为:面向切面编程,通过预编译方式和运行期动态代理实现程序功能的统一维护的一种技术。AOP是Spring框架中的一个重要内容,它通过对既有程序定义一个切入点,然后在其前后切入不同的执行内容,比如常见的有:打开数据库连接/关闭数据库连接、打开事务/关闭事务、记录日志等。基于AOP不会破坏原来程序逻辑,因此它可以很好的对业务逻辑的各个部分进行隔离,从而使得业务逻辑各部分之间的耦合度降低,提高程序的可重用性,同时提高了开发的效率。

下面主要讲两个内容,一个是如何在Spring Boot中引入Aop功能,二是如何使用Aop做切面去统一处理Web请求的日志。

一、准备工作

因为需要对web请求做切面来记录日志,所以先引入web模块,并创建一个简单的hello请求的处理。
1、pom.xml中引入web模块

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
</dependency>

2、实现一个简单请求处理:通过传入name参数,返回“hello xxx”的功能。

package com.example.aopproxy.controller;

import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.ResponseBody;
import org.springframework.web.bind.annotation.RestController;

/**
 * @author: kaiyi
 * @create: 2020-10-18 10:17
 */
@RestController
public class HelloController {

  @RequestMapping(value = "/hello", method = RequestMethod.GET)
  @ResponseBody
  public String hello(@RequestParam String name) {
    return "Hello " + name;
  }

  @RequestMapping(value = "/info", method = RequestMethod.GET)
  @ResponseBody
  public String info(@RequestParam(value="name") String name, @RequestParam(value="age") Integer age) {
    return "Info: " + name + "age:" + age;
  }
}

下面,我们可以对上面的/hello请求,进行切面日志记录。

二、引入AOP依赖

在Spring Boot中引入AOP就跟引入其他模块一样,非常简单,只需要在 pom.xml 中加入如下依赖:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

在完成了引入AOP依赖包后,一般来说并不需要去做其他配置。也许在Spring中使用过注解配置方式的人会问是否需要在程序主类中增加@EnableAspectJAutoProxy来启用,实际并不需要。

可以看下面关于AOP的默认配置属性,其中spring.aop.auto属性默认是开启的,也就是说只要引入了AOP依赖后,默认已经增加了@EnableAspectJAutoProxy

# AOP
spring.aop.auto=true # Add @EnableAspectJAutoProxy.
spring.aop.proxy-target-class=false # Whether subclass-based (CGLIB) proxies are to be created (true) as
 opposed to standard Java interface-based proxies (false).

而当我们需要使用CGLIB来实现AOP的时候,需要配置 spring.aop.proxy-target-class=true,不然默认使用的是标准Java的实现。

三、实现Web层的日志切面

springboot中使用@Slf4j进行日志输出

  • 引入lombok
  • 类上面添加@Slf4j,然后在代码写入一下内容即可

只需要在 pom.xml 中加入如下依赖:

 <dependency>
      <groupId>org.projectlombok</groupId>
      <artifactId>lombok</artifactId>
    </dependency>

使用方法:

// 在类上面加上注解@Slf4j,或者:private final static Logger log= LoggerFactory.getLogger(UserController.class);
log.info(123)

AOP切面实现

实现AOP的切面主要有以下几个要素:

  • 使用@Aspect注解将一个java类定义为切面类
  • 使用@Pointcut定义一个切入点,可以是一个规则表达式,比如下例中某个package下的所有函数,也可以是一个注解等。
  • 根据需要在切入点不同位置的切入内容
    • 使用@Before在切入点开始处切入内容
    • 使用@After在切入点结尾处切入内容
    • 使用@AfterReturning在切入点return内容之后切入内容(可以用来对处理返回值做一些加工处理)
    • 使用@Around在切入点前后切入内容,并自己控制何时执行切入点自身的内容
    • 使用@AfterThrowing用来处理当切入内容部分抛出异常之后的处理逻辑
package com.example.aopproxy.aop;

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestAttributes;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;
import java.util.Arrays;

/**
 * @author: kaiyi
 * @create: 2020-10-18 10:19
 */
@Slf4j
@Aspect
@Component
public class WebLogAspect {

  // 切入点描述 这个是controller包的切入点
  @Pointcut("execution(public * com.example.aopproxy.controller..*.*(..))")
  public void webLog(){} //签名,可以理解成这个切入点的一个名称

  @Before("webLog()")
  public void doBefore(JoinPoint joinPoint) throws Throwable{
    //这个RequestContextHolder是Springmvc提供来获得请求的东西
    RequestAttributes requestAttributes = RequestContextHolder.getRequestAttributes();
    HttpServletRequest request = ((ServletRequestAttributes)requestAttributes).getRequest();

    // 记录下请求内容
    log.info("URL : " + request.getRequestURL().toString());
    log.info("HTTP_METHOD : " + request.getMethod());
    log.info("IP : " + request.getRemoteAddr());

    //下面这个getSignature().getDeclaringTypeName()是获取包+类名的   然后后面的joinPoint.getSignature.getName()获取了方法名
    log.info("CLASS_METHOD : " + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());
    log.info("ARGS : " + Arrays.toString(joinPoint.getArgs()));

    log.info("################TARGET: " + joinPoint.getTarget()); //返回的是需要加强的目标类的对象
    log.info("################THIS: " + joinPoint.getThis()); //返回的是经过加强后的代理类的对象
  }

  @AfterReturning(returning = "ret", pointcut = "webLog()")
  public void doAfterReturning(Object ret) throws Throwable {
    // 处理完请求,返回内容
    log.info("RESPONSE : " + ret);
  }

}

可以看上面的例子,通过@Pointcut定义的切入点为com.example.aopproxy.controller包下的所有函数(对web层所有请求处理做切入点),然后通过@Before实现,对请求内容的日志记录(本文只是说明过程,可以根据需要调整内容),最后通过@AfterReturning记录请求返回的对象。

通过运行程序并访问:http://localhost:8080/hello?name=lily&age=10,可以获得下面的日志输出

2020-10-18 10:44:56.653  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : URL : http://localhost:8080/hello
2020-10-18 10:44:56.653  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : HTTP_METHOD : GET
2020-10-18 10:44:56.653  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : IP : 0:0:0:0:0:0:0:1
2020-10-18 10:44:56.653  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : CLASS_METHOD : com.example.aopproxy.controller.HelloController.hello
2020-10-18 10:44:56.653  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : ARGS : [lily]
2020-10-18 10:44:56.653  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : ################TARGET: com.example.aopproxy.controller.HelloController@5dda3a9b
2020-10-18 10:44:56.654  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : ################THIS: com.example.aopproxy.controller.HelloController@5dda3a9b
2020-10-18 10:44:56.654  INFO 31211 --- [nio-8080-exec-2] com.example.aopproxy.aop.WebLogAspect    : RESPONSE : Hello lily

四、代码解析

针对这个切面类,来展开说明@Aspect切面类的编程。

@Aspect和@Component

首先,这个@Aspect注释告诉Spring这是个切面类,然后@Compoment将转换成Spring容器中的bean或者是代理bean。 总之要写切面这两个注解一起用就是了。

既然是切面类,那么肯定是包含PointCut还有Advice两个要素的,下面对几个注解展开讲来看看在@Aspect中是怎么确定切入点(PointCut)和增强通知(Advice)的。

@PointCut

这个注解包含两部分,PointCut表达式和PointCut签名。表达式是拿来确定切入点的位置的,说白了就是通过一些规则来确定,哪些方法是要增强的,也就是要拦截哪些方法。

@PointCut(...........)括号里面那些就是表达式。这里的execution是其中的一种匹配方式,还有:

execution: 匹配连接点

within: 某个类里面

this: 指定AOP代理类的类型

target:指定目标对象的类型

args: 指定参数的类型

bean:指定特定的bean名称,可以使用通配符(Spring自带的)

@target: 带有指定注解的类型

@args: 指定运行时传的参数带有指定的注解

@within: 匹配使用指定注解的类

@annotation:指定方法所应用的注解

注意,由于是动态代理的实现方法,所以不是所有的方法都能拦截得下来,对于JDK代理只有public的方法才能拦截得下来,对于CGLIB只有public和protected的方法才能拦截。

这里我们主要介绍execution的匹配方法,因为大多数时候都会用这个来定义pointcut:

execution(modifiers-pattern? ret-type-pattern declaring-type-pattern?name-pattern(param-pattern)
            throws-pattern?)

execution(方法修饰符(可选)  返回类型  类路径 方法名  参数  异常模式(可选)) 

除了返回类型,方法名还有参数之外,其他都是可选的

ret-type-pattern:可以为*表示任何返回值,全路径的类名等.

name-pattern:指定方法名,代表所以,set,代表以set开头的所有方法.
parameters pattern:指定方法参数(声明的类型), ()匹配没有参数; (..)代表任意多个参数; ()代表一个参数,但可以是任意型; (,String)代表第一个参数为任何值,第二个为String类型。

下面给几个例子:

1)execution(public * *(..))——表示匹配所有public方法
2)execution(* set*(..))——表示所有以“set”开头的方法
3)execution(* com.xyz.service.AccountService.*(..))——表示匹配所有AccountService接口的方法
4)execution(* com.xyz.service.*.*(..))——表示匹配service包下所有的方法
5)execution(* com.xyz.service..*.*(..))——表示匹配service包和它的子包下的方法

RequestContextHolder

好了现在注解都介绍完了,这里还要提到上面用到的一个类:RequestContextHolder

比如说,有个需求需要在service中获得request和response,我们一般会(我就是)直接在controller那把request或response作为参数传到service,这就很不美观。后来知道,原来SpringMVC提供了个很强大的类ReqeustContextHolder,通过他你就可以获得request和response什么的。

//下面两个方法在没有使用JSF的项目中是没有区别的
RequestAttributes requestAttributes = RequestContextHolder.currentRequestAttributes();
//                                            RequestContextHolder.getRequestAttributes();
//从session里面获取对应的值
String str = (String) requestAttributes.getAttribute("name",RequestAttributes.SCOPE_SESSION);

HttpServletRequest request = ((ServletRequestAttributes)requestAttributes).getRequest();
HttpServletResponse response = ((ServletRequestAttributes)requestAttributes).getResponse();

五、优化切面

优化:AOP切面中的同步问题
在WebLogAspect切面中,分别通过doBefore和doAfterReturning两个独立函数实现了切点头部和切点返回后执行的内容,若我们想统计请求的处理时间,就需要在doBefore处记录时间,并在doAfterReturning处通过当前时间与开始处记录的时间计算得到请求处理的消耗时间。

那么我们是否可以在WebLogAspect切面中定义一个成员变量来给doBefore和doAfterReturning一起访问呢?是否会有同步问题呢?

的确,直接在这里定义基本类型会有同步问题,所以我们可以引入ThreadLocal对象,像下面这样进行记录:

@Aspect
@Component
public class WebLogAspect {

    private Logger logger = Logger.getLogger(getClass());

    ThreadLocal<Long> startTime = new ThreadLocal<>();

    @Pointcut("execution(public * com.didispace.web..*.*(..))")
    public void webLog(){}

    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) throws Throwable {
        startTime.set(System.currentTimeMillis());

        // 省略日志记录内容
    }

    @AfterReturning(returning = "ret", pointcut = "webLog()")
    public void doAfterReturning(Object ret) throws Throwable {
        // 处理完请求,返回内容
        logger.info("RESPONSE : " + ret);
        logger.info("SPEND TIME : " + (System.currentTimeMillis() - startTime.get()));
    }
}

优化:AOP切面的优先级
由于通过AOP实现,程序得到了很好的解耦,但是也会带来一些问题,比如:我们可能会对Web层做多个切面,校验用户,校验头信息等等,这个时候经常会碰到切面的处理顺序问题。

所以,我们需要定义每个切面的优先级,我们需要@Order(i)注解来标识切面的优先级。i的值越小,优先级越高。假设我们还有一个切面是CheckNameAspect用来校验name必须为didi,我们为其设置@Order(10),而上文中WebLogAspect设置为@Order(5),所以WebLogAspect有更高的优先级,这个时候执行顺序是这样的:

在@Before中优先执行@Order(5)的内容,再执行@Order(10)的内容
@After@AfterReturning中优先执行@Order(10)的内容,再执行@Order(5)的内容

所以我们可以这样子总结:

  • 在切入点前的操作,按order的值由小到大执行
  • 在切入点后的操作,按order的值由大到小执行

相关文章:
springboot aop简单示例
在SpringBoot中用SpringAOP实现日志记录功能
Java日志框架SLF4J和log4j以及logback的联系和区别
springboot日志输出整合slf4j

为者常成,行者常至