SpringCloud（第 048 篇）使用AOP统一处理Web请求日志

-

一、大致介绍

1、AOP是Spring框架中的一个重要内容，它通过对既有程序定义一个切入点，然后在其前后切入不同的执行内容，比如常见的有：打开数据库连接/关闭数据库连接、打开事务/关闭事务、记录日志等；2、基于AOP不会破坏原来程序逻辑，因此它可以很好的对业务逻辑的各个部分进行隔离，从而使得业务逻辑各部分之间的耦合度降低，提高程序的可重用性，同时提高了开发的效率。

二、实现步骤

2.1 添加 maven 引用包

<?xml version="1.0" encoding="UTF-8"?><project xmlns="http://maven.apache.org/POM/4.0.0"         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">    <modelVersion>4.0.0</modelVersion>    <artifactId>springms-aop-weblog</artifactId>    <version>1.0-SNAPSHOT</version>    <packaging>jar</packaging>    <parent>        <groupId>com.springms.cloud</groupId>        <artifactId>springms-spring-cloud</artifactId>        <version>1.0-SNAPSHOT</version>    </parent>    <dependencies>        <!-- 访问数据库模块 -->        <dependency>            <groupId>org.springframework.boot</groupId>            <artifactId>spring-boot-starter-data-jpa</artifactId>        </dependency>        <!-- web模块 -->        <dependency>            <groupId>org.springframework.boot</groupId>            <artifactId>spring-boot-starter-web</artifactId>        </dependency>        <!-- h2数据库模块 -->        <dependency>            <groupId>com.h2database</groupId>            <artifactId>h2</artifactId>            <scope>runtime</scope>        </dependency>        <!-- 支持Apache Solr搜索平台，包括spring-data-solr -->        <dependency>            <groupId>org.springframework.boot</groupId>            <artifactId>spring-boot-starter-data-solr</artifactId>        </dependency>    </dependencies></project>

2.2 添加应用配置文件（springms-aop-weblog\src\main\resources\application.yml）

server:  port: 8350spring:  application:    name: springms-aop-weblog  #全部小写  jpa:    generate-ddl: false    show-sql: true    hibernate:      ddl-auto: none  datasource:    platform: h2    schema: classpath:schema.sql    data: classpath:data.sql

2.3 添加 H2 数据库脚本（springms-aop-weblog\src\main\resources\schema.sql）

drop table user if exists;CREATE TABLE USER(    id BIGINT GENERATED by default as identity,    username VARCHAR(40),    name VARCHAR(20),    age int(3),    balance DECIMAL(10, 2),    PRIMARY KEY(id));

2.4 插入 H2 数据库一些初始化数据（springms-aop-weblog\src\main\resources\data.sql）

INSERT into user (id, username, name, age, balance) values (1, 'user1', '张三', 20, 100.00);INSERT into user (id, username, name, age, balance) values (2, 'user2', '李四', 22, 100.00);INSERT into user (id, username, name, age, balance) values (3, 'user3', '王五', 24, 100.00);INSERT into user (id, username, name, age, balance) values (4, 'user4', '赵六', 26, 100.00);INSERT into user (id, username, name, age, balance) values (5, 'user5', '李逵', 27, 100.00);INSERT into user (id, username, name, age, balance) values (6, 'user6', '张远', 10, 100.00);INSERT into user (id, username, name, age, balance) values (7, 'user7', '迪拜', 60, 100.00);INSERT into user (id, username, name, age, balance) values (8, 'user8', '哈士奇', 40, 100.00);INSERT into user (id, username, name, age, balance) values (9, 'user9', '关羽', 30, 100.00);

2.5 添加访问底层数据模型的DAO接口（springms-aop-weblog\src\main\java\com\springms\cloud\repository\UserRepository.java）

package com.springms.cloud.repository;import com.springms.cloud.entity.User;import org.springframework.data.jpa.repository.JpaRepository;import org.springframework.stereotype.Repository;@Repositorypublic interface UserRepository extends JpaRepository<User, Long> {}

2.6 添加实体用户类User（springms-aop-weblog\src\main\java\com\springms\cloud\entity\User.java）

package com.springms.cloud.entity;import java.math.BigDecimal;import javax.persistence.Column;import javax.persistence.Entity;import javax.persistence.GeneratedValue;import javax.persistence.GenerationType;import javax.persistence.Id;@Entitypublic class User {  @Id  @GeneratedValue(strategy = GenerationType.AUTO)  private Long id;  @Column  private String username;  @Column  private String name;  @Column  private Short age;  @Column  private BigDecimal balance;  public Long getId() {    return this.id;  }  public void setId(Long id) {    this.id = id;  }  public String getUsername() {    return this.username;  }  public void setUsername(String username) {    this.username = username;  }  public String getName() {    return this.name;  }  public void setName(String name) {    this.name = name;  }  public Short getAge() {    return this.age;  }  public void setAge(Short age) {    this.age = age;  }  public BigDecimal getBalance() {    return this.balance;  }  public void setBalance(BigDecimal balance) {    this.balance = balance;  }}

2.7 添加Web层日志切面@Order(1)（springms-aop-weblog\src\main\java\com\springms\cloud\controller\UserController.java）

package com.springms.cloud.aop;import org.apache.log4j.Logger;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.core.annotation.Order;import org.springframework.stereotype.Component;import org.springframework.web.context.request.RequestContextHolder;import org.springframework.web.context.request.ServletRequestAttributes;import javax.servlet.http.HttpServletRequest;import java.util.Arrays;/**************************************************************************************** 实现AOP的切面主要有以下几个要素： 使用@Aspect注解将一个java类定义为切面类 使用@Pointcut定义一个切入点，可以是一个规则表达式，比如下例中某个package下的所有函数，也可以是一个注解等。 根据需要在切入点不同位置的切入内容 使用@Before在切入点开始处切入内容 使用@After在切入点结尾处切入内容 使用@AfterReturning在切入点return内容之后切入内容（可以用来对处理返回值做一些加工处理） 使用@Around在切入点前后切入内容，并自己控制何时执行切入点自身的内容 使用@AfterThrowing用来处理当切入内容部分抛出异常之后的处理逻辑 使用@Order(i)注解来标识切面的优先级。i的值越小，优先级越高 ****************************************************************************************//**************************************************************************************** 执行日志顺序： 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) URL : http://localhost:8350/simple/1 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) HTTP_METHOD : GET 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) IP : 127.0.0.1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) CLASS_METHOD : com.springms.cloud.controller.SimpleProviderUserAopWebLogController.findById 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) ARGS : [1] 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) URL : http://localhost:8350/simple/1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) HTTP_METHOD : GET 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) IP : 127.0.0.1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) CLASS_METHOD : com.springms.cloud.controller.SimpleProviderUserAopWebLogController.findById 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) ARGS : [1] Hibernate: select user0_.id as id1_0_0_, user0_.age as age2_0_0_, user0_.balance as balance3_0_0_, user0_.name as name4_0_0_, user0_.username as username5_0_0_ from user user0_ where user0_.id=? 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doAfterReturning) RESPONSE : User@1249202 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doAfterReturning) SPEND TIME : 42 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doAfterReturning) RESPONSE : User@1249202 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doAfterReturning) SPEND TIME : 43 总结：doBefore 方法先从优先级到低优先级依次执行完，然后 doAfterReturning 方法从低优先级到高优先级依次执行完；也就是进入从高到低，出来从低到高； ****************************************************************************************//** * Web层日志切面。 * * @author hmilyylimh * * @version 0.0.1 * * @date 2017/10/19 * */@Aspect@Order(1)@Componentpublic class WebLogHeadAspect {    // private static final org.slf4j.Logger logger = LoggerFactory.getLogger(PreZuulFilter.class);    private Logger logger = Logger.getLogger(getClass());    ThreadLocal<Long> startTime = new ThreadLocal<>();    private static final String PRE_TAG = "(Order(1))************** ";    @Pointcut("execution(public * com.springms.cloud.controller..*.*(..))")    public void webLog(){}    @Before("webLog()")    public void doBefore(JoinPoint joinPoint) throws Throwable {        startTime.set(System.currentTimeMillis());        // 接收到请求，记录请求内容        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();        HttpServletRequest request = attributes.getRequest();        // 记录下请求内容        logger.info(PRE_TAG + "(doBefore) URL : " + request.getRequestURL().toString());        logger.info(PRE_TAG + "(doBefore) HTTP_METHOD : " + request.getMethod());        logger.info(PRE_TAG + "(doBefore) IP : " + request.getRemoteAddr());        logger.info(PRE_TAG + "(doBefore) CLASS_METHOD : " + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());        logger.info(PRE_TAG + "(doBefore) ARGS : " + Arrays.toString(joinPoint.getArgs()));    }    @AfterReturning(returning = "ret", pointcut = "webLog()")    public void doAfterReturning(Object ret) throws Throwable {        // 处理完请求，返回内容        logger.info(PRE_TAG + "(doAfterReturning) RESPONSE : " + ret);        logger.info(PRE_TAG + "(doAfterReturning) SPEND TIME : " + (System.currentTimeMillis() - startTime.get()));    }}

2.8 添加Web层日志切面@Order(5)（springms-aop-weblog\src\main\java\com\springms\cloud\controller\UserController.java）

package com.springms.cloud.aop;import org.apache.log4j.Logger;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.core.annotation.Order;import org.springframework.stereotype.Component;import org.springframework.web.context.request.RequestContextHolder;import org.springframework.web.context.request.ServletRequestAttributes;import javax.servlet.http.HttpServletRequest;import java.util.Arrays;/**************************************************************************************** 实现AOP的切面主要有以下几个要素： 使用@Aspect注解将一个java类定义为切面类 使用@Pointcut定义一个切入点，可以是一个规则表达式，比如下例中某个package下的所有函数，也可以是一个注解等。 根据需要在切入点不同位置的切入内容 使用@Before在切入点开始处切入内容 使用@After在切入点结尾处切入内容 使用@AfterReturning在切入点return内容之后切入内容（可以用来对处理返回值做一些加工处理） 使用@Around在切入点前后切入内容，并自己控制何时执行切入点自身的内容 使用@AfterThrowing用来处理当切入内容部分抛出异常之后的处理逻辑 使用@Order(i)注解来标识切面的优先级。i的值越小，优先级越高 ****************************************************************************************//**************************************************************************************** 执行日志顺序： 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) URL : http://localhost:8350/simple/1 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) HTTP_METHOD : GET 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) IP : 127.0.0.1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) CLASS_METHOD : com.springms.cloud.controller.SimpleProviderUserAopWebLogController.findById 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) ARGS : [1] 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) URL : http://localhost:8350/simple/1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) HTTP_METHOD : GET 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) IP : 127.0.0.1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) CLASS_METHOD : com.springms.cloud.controller.SimpleProviderUserAopWebLogController.findById 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) ARGS : [1] Hibernate: select user0_.id as id1_0_0_, user0_.age as age2_0_0_, user0_.balance as balance3_0_0_, user0_.name as name4_0_0_, user0_.username as username5_0_0_ from user user0_ where user0_.id=? 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doAfterReturning) RESPONSE : User@1249202 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doAfterReturning) SPEND TIME : 42 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doAfterReturning) RESPONSE : User@1249202 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doAfterReturning) SPEND TIME : 43 总结：doBefore 方法先从优先级到低优先级依次执行完，然后 doAfterReturning 方法从低优先级到高优先级依次执行完；也就是进入从高到低，出来从低到高； ****************************************************************************************//** * Web层日志切面。 * * @author hmilyylimh * * @version 0.0.1 * * @date 2017/10/19 * */@Aspect@Order(5)@Componentpublic class WebLogFiveAspect {    // private static final org.slf4j.Logger logger = LoggerFactory.getLogger(PreZuulFilter.class);    private Logger logger = Logger.getLogger(getClass());    ThreadLocal<Long> startTime = new ThreadLocal<>();    private static final String PRE_TAG = "(Order(5))============== ";    @Pointcut("execution(public * com.springms.cloud.controller..*.*(..))")    public void webLog(){}    @Before("webLog()")    public void doBefore(JoinPoint joinPoint) throws Throwable {        startTime.set(System.currentTimeMillis());        // 接收到请求，记录请求内容        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();        HttpServletRequest request = attributes.getRequest();        // 记录下请求内容        logger.info(PRE_TAG + "(doBefore) URL : " + request.getRequestURL().toString());        logger.info(PRE_TAG + "(doBefore) HTTP_METHOD : " + request.getMethod());        logger.info(PRE_TAG + "(doBefore) IP : " + request.getRemoteAddr());        logger.info(PRE_TAG + "(doBefore) CLASS_METHOD : " + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());        logger.info(PRE_TAG + "(doBefore) ARGS : " + Arrays.toString(joinPoint.getArgs()));    }    @AfterReturning(returning = "ret", pointcut = "webLog()")    public void doAfterReturning(Object ret) throws Throwable {        // 处理完请求，返回内容        logger.info(PRE_TAG + "(doAfterReturning) RESPONSE : " + ret);        logger.info(PRE_TAG + "(doAfterReturning) SPEND TIME : " + (System.currentTimeMillis() - startTime.get()));    }}

2.9 添加用户Web访问层Controller（springms-aop-weblog\src\main\java\com\springms\cloud\controller\UserController.java）

package com.springms.cloud.controller;import com.springms.cloud.entity.User;import org.springframework.beans.factory.annotation.Autowired;import org.springframework.web.bind.annotation.GetMapping;import org.springframework.web.bind.annotation.PathVariable;import org.springframework.web.bind.annotation.RestController;import com.springms.cloud.repository.UserRepository;/** * 用户微服务Controller。 * * @author hmilyylimh * * @version 0.0.1 * * @date 2017/10/19 * */@RestControllerpublic class AopWebLogController {    @Autowired    private UserRepository userRepository;    @GetMapping("/simple/{id}")    public User findById(@PathVariable Long id) {        return this.userRepository.findOne(id);    }}

2.10 添加微服务启动类（springms-aop-weblog\src\main\java\com\springms\cloud\MsAopWebLogApplication.java）

package com.springms.cloud;import org.springframework.boot.SpringApplication;import org.springframework.boot.autoconfigure.SpringBootApplication;/** * 使用AOP统一处理Web请求日志。 * * @author hmilyylimh * * @version 0.0.1 * * @date 2017/10/19 * */@SpringBootApplicationpublic class MsAopWebLogApplication {    public static void main(String[] args) {        SpringApplication.run(MsAopWebLogApplication.class, args);        System.out.println("【【【【【【 AopWebLog微服务 】】】】】】已启动.");    }}

三、测试

/**************************************************************************************** 一、简单用户微服务类（实现AOP的切面打印日志）： 1、启动 springms-aop-weblog 模块服务，启动1个端口； 2、在浏览器输入地址 http://localhost:8350/simple/1 可以看到日志信息成功的被打印出来到控制台上。； 执行日志顺序： 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) URL : http://localhost:8350/simple/1 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) HTTP_METHOD : GET 2017-10-19 20:22:35.810  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) IP : 127.0.0.1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) CLASS_METHOD : com.springms.cloud.controller.SimpleProviderUserAopWebLogController.findById 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doBefore) ARGS : [1] 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) URL : http://localhost:8350/simple/1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) HTTP_METHOD : GET 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) IP : 127.0.0.1 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) CLASS_METHOD : com.springms.cloud.controller.SimpleProviderUserAopWebLogController.findById 2017-10-19 20:22:35.811  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doBefore) ARGS : [1] Hibernate: select user0_.id as id1_0_0_, user0_.age as age2_0_0_, user0_.balance as balance3_0_0_, user0_.name as name4_0_0_, user0_.username as username5_0_0_ from user user0_ where user0_.id=? 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doAfterReturning) RESPONSE : User@1249202 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] com.springms.cloud.aop.WebLogFiveAspect        : (Order(5))============== (doAfterReturning) SPEND TIME : 42 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doAfterReturning) RESPONSE : User@1249202 2017-10-19 20:22:35.853  INFO 9014 --- [nio-8350-exec-1] WebLogHeadAspect    : (Order(1))************** (doAfterReturning) SPEND TIME : 43 总结：doBefore 方法先从优先级到低优先级依次执行完，然后 doAfterReturning 方法从低优先级到高优先级依次执行完；也就是进入从高到低，出来从低到高； ****************************************************************************************/

四、下载地址

https://gitee.com/ylimhhmily/SpringCloudTutorial.git

SpringCloudTutorial交流QQ群: 235322432

SpringCloudTutorial交流微信群: 微信沟通群二维码图片链接

欢迎关注，您的肯定是对我最大的支持!!!