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

原文：http://blog.didispace.com/springbootaoplog/

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

    在阅读了以上代码后，我自己进行了测试，可以在log文件和Consol中打印出相关的log。

    2018-11-23 11:33:39.448  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : URL : http://localhost:8080/guest/enter
    2018-11-23 11:33:39.448  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : HTTP_METHOD : GET
    2018-11-23 11:33:39.448  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : IP : 0:0:0:0:0:0:0:1
    2018-11-23 11:33:39.449  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : CLASS_METHOD : com.learning.www.controller.GuestController.login
    2018-11-23 11:33:39.449  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : ARGS : []
    2018-11-23 11:33:39.455  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : URL : http://localhost:8080/guest/enter
    2018-11-23 11:33:39.455  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : HTTP_METHOD : GET
    2018-11-23 11:33:39.455  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : IP : 0:0:0:0:0:0:0:1
    2018-11-23 11:33:39.455  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : CLASS_METHOD : com.learning.www.controller.ResultMap.success
    2018-11-23 11:33:39.455  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : ARGS : []
    2018-11-23 11:33:39.466  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : RESPONSE : {result=success}
    2018-11-23 11:33:39.467  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : URL : http://localhost:8080/guest/enter
    2018-11-23 11:33:39.467  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : HTTP_METHOD : GET
    2018-11-23 11:33:39.467  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : IP : 0:0:0:0:0:0:0:1
    2018-11-23 11:33:39.467  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : CLASS_METHOD : com.learning.www.controller.ResultMap.message
    2018-11-23 11:33:39.467  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : ARGS : [欢迎进入，您的身份是游客]
    2018-11-23 11:33:39.467  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : RESPONSE : {result=success, message=欢迎进入，您的身份是游客}
    2018-11-23 11:33:39.469  INFO 5660 --- [nio-8080-exec-1] c.l.www.controller.LoginController       : RESPONSE : {result=success, message=欢迎进入，您的身份是游客}
    2018-11-23 11:33:39.496  INFO 5660 --- [nio-8080-exec-3] c.l.www.controller.LoginController       : URL : http://localhost:8080/notLogin
    2018-11-23 11:33:39.496  INFO 5660 --- [nio-8080-exec-3] c.l.www.controller.LoginController       : HTTP_METHOD : GET
    2018-11-23 11:33:39.496  INFO 5660 --- [nio-8080-exec-3] c.l.www.controller.LoginController       : IP : 0:0:0:0:0:0:0:1
    2018-11-23 11:33:39.496  INFO 5660 --- [nio-8080-exec-3] c.l.www.controller.LoginController       : CLASS_METHOD : com.learning.www.controller.LoginController.notLogin
    2018-11-23 11:33:39.496  INFO 5660 --- [nio-8080-exec-3] c.l.www.controller.LoginController       : ARGS : []
    2018-11-23 11:33:39.498  INFO 5660 --- [nio-8080-exec-3] c.l.www.controller.LoginController       : RESPONSE : login