Spring Boot 使用AOP统一处理Web请求日志

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

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

准备工做

由于须要对web请求作切面来记录日志，因此先引入web模块，并建立一个简单的hello请求的处理。

• pom.xml中引入web模块

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

• 实现一个简单请求处理：经过传入name参数，返回“hello xxx”的功能。

@RestController
public class HelloController {

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

}

下面，咱们能够对上面的/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层的日志切面

实现AOP的切面主要有如下几个要素：

• 使用@Aspect注解将一个java类定义为切面类
• 使用@Pointcut定义一个切入点，能够是一个规则表达式，好比下例中某个package下的全部函数，也能够是一个注解等。
• 根据须要在切入点不一样位置的切入内容
  • 使用@Before在切入点开始处切入内容
  • 使用@After在切入点结尾处切入内容
  • 使用@AfterReturning在切入点return内容以后切入内容（能够用来对处理返回值作一些加工处理）
  • 使用@Around在切入点先后切入内容，并本身控制什么时候执行切入点自身的内容
  • 使用@AfterThrowing用来处理当切入内容部分抛出异常以后的处理逻辑

@Aspect
@Component
public class WebLogAspect {

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

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

    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) throws Throwable {
        // 接收到请求，记录请求内容
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();

        // 记录下请求内容
        logger.info("URL : " + request.getRequestURL().toString());
        logger.info("HTTP_METHOD : " + request.getMethod());
        logger.info("IP : " + request.getRemoteAddr());
        logger.info("CLASS_METHOD : " + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());
        logger.info("ARGS : " + Arrays.toString(joinPoint.getArgs()));

    }

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

}

能够看上面的例子，经过@Pointcut定义的切入点为com.didispace.web包下的全部函数（对web层全部请求处理作切入点），而后经过@Before实现，对请求内容的日志记录（本文只是说明过程，能够根据须要调整内容），最后经过@AfterReturning记录请求返回的对象。

经过运行程序并访问：http://localhost:8080/hello?name=didi，能够得到下面的日志输出

2016-05-19 13:42:13,156  INFO WebLogAspect:41 - URL : http://localhost:8080/hello
2016-05-19 13:42:13,156  INFO WebLogAspect:42 - HTTP_METHOD : http://localhost:8080/hello
2016-05-19 13:42:13,157  INFO WebLogAspect:43 - IP : 0:0:0:0:0:0:0:1
2016-05-19 13:42:13,160  INFO WebLogAspect:44 - CLASS_METHOD : com.didispace.web.HelloController.hello
2016-05-19 13:42:13,160  INFO WebLogAspect:45 - ARGS : [didi]
2016-05-19 13:42:13,170  INFO WebLogAspect:52 - RESPONSE:Hello didi

优化：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的值由大到小执行