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: 8350
spring:
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;
@Repository
public 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;
@Entity
public 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)
@Component
public 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)
@Component
public 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
*
*/
@RestController
public 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
*
*/
@SpringBootApplication
public 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交流微信群: 微信沟通群二维码图片链接
欢迎关注，您的肯定是对我最大的支持!!!
