Spring Boot - AOP + Log 实现日志处理

Spring Boot 2.2.4.RELEASE

数据库：MySQL

AOP 的核心概念

名词	概念	理解
通知（Advice）	拦截到连接点之后所要执行的代码，通知分为前置、后置、异常、最终、环绕通知五类	我们要实现的功能，如日志记录，性能统计，安全控制，事务处理，异常处理等等，说明什么时候要干什么
连接点（Joint Point）	被拦截到的点，如被拦截的方法、对类成员的访问以及异常处理程序块的执行等等，自身还能嵌套其他的 Joint Point	Spring 允许你用通知的地方，方法有关的前前后后（包括抛出异常）
切入点（Pointcut）	对连接点进行拦截的定义	指定通知到哪个方法，说明在哪干
切面（Aspect）	切面类的定义，里面包含了切入点（Pointcut）和通知（Advice）的定义	切面就是通知和切入点的结合
目标对象（Target Object）	切入点选择的对象，也就是需要被通知的对象；由于 Spring AOP 通过代理模式实现，所以该对象永远是被代理对象	业务逻辑本身
织入（Weaving）	把切面应用到目标对象从而创建出 AOP 代理对象的过程。织入可以在编译期、类装载期、运行期进行，而 Spring 采用在运行期完成	切点定义了哪些连接点会得到通知
引入（Introduction ）	可以在运行期为类动态添加方法和字段，Spring 允许引入新的接口到所有目标对象	引入就是在一个接口/类的基础上引入新的接口增强功能
AOP 代理（AOP Proxy ）	Spring AOP 可以使用 JDK 动态代理或者 CGLIB 代理，前者基于接口，后者基于类	通过代理来对目标对象应用切面

Spring AOP

简介

AOP 是 Spring 框架中的一个核心内容。在 Spring 中，AOP 代理可以用 JDK 动态代理或者 CGLIB 代理。Spring 中 AOP 代理由 Spring 的 IOC 容器负责生成和管理，其依赖关系也由 IOC 容器负责管理。

相关注解

注解	说明
@Aspect	将一个 java 类定义为切面类
@Pointcut	定义一个切入点，可以是一个规则表达式，比如下例中某个 package 下的所有函数，也可以是一个注解等
@Before	在切入点开始处切入内容
@After	在切入点结尾处切入内容
@AfterReturning	在切入点 return 内容之后处理逻辑
@Around	在切入点前后切入内容，并自己控制何时执行切入点自身的内容
@AfterThrowing	用来处理当切入内容部分抛出异常之后的处理逻辑
@Order(100)	AOP 切面执行顺序， @Before 数值越小越先执行，@After 和 @AfterReturning 数值越大越先执行

其中 @Before、@After、@AfterReturning、@Around、@AfterThrowing 都属于通知（Advice）。

数据库表定义

mysql> desc sys_request_log;
+---------------------+--------------+------+-----+---------+----------------+
| Field               | Type         | Null | Key | Default | Extra          |
+---------------------+--------------+------+-----+---------+----------------+
| id                  | int(11)      | NO   | PRI | NULL    | auto_increment |
| username            | varchar(255) | YES  |     | NULL    |                |
| user_agent          | varchar(255) | YES  |     | NULL    |                |
| request_url         | varchar(255) | YES  |     | NULL    |                |
| ip                  | varchar(255) | YES  |     | NULL    |                |
| declaring_signature | varchar(255) | YES  |     | NULL    |                |
| args                | varchar(255) | YES  |     | NULL    |                |
| exception           | varchar(255) | YES  |     | NULL    |                |
| elapsed_time        | int(11)      | YES  |     | NULL    |                |
| create_time         | datetime     | YES  |     | NULL    |                |
+---------------------+--------------+------+-----+---------+----------------+
10 rows in set (0.00 sec)

mysql> show create table sys_request_log \G
*************************** 1. row ***************************
       Table: sys_request_log
Create Table: CREATE TABLE `sys_request_log` (
  `id` int(11) NOT NULL AUTO_INCREMENT COMMENT '编号',
  `username` varchar(255) CHARACTER SET utf8 COLLATE utf8_bin DEFAULT NULL COMMENT '用户名',
  `user_agent` varchar(255) DEFAULT NULL COMMENT '用户代理（客户端）',
  `request_url` varchar(255) DEFAULT NULL COMMENT '请求 URL',
  `ip` varchar(255) DEFAULT NULL COMMENT 'IP',
  `declaring_signature` varchar(255) DEFAULT NULL COMMENT '请求方法',
  `args` varchar(255) DEFAULT NULL COMMENT '请求参数',
  `exception` varchar(255) DEFAULT NULL COMMENT '异常',
  `elapsed_time` int(11) DEFAULT NULL COMMENT '耗时，单位毫秒',
  `create_time` datetime DEFAULT NULL COMMENT '创建时间',
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

AOP 实现 Web 日志处理

思路：使用 AOP 针对控制器的请求进行记录，然后通过日志输出，并异步保存到数据库。

新建 Spring Boot 项目，引入依赖：

1. 数据库驱动
2. Druid 数据源
3. MyBatis Plus

<?xml version="1.0" encoding="UTF-8"?>
<project>
    <properties>
        <java.version>1.8</java.version>
        <mysql-connector-java.version>5.1.40</mysql-connector-java.version>
        <druid-spring-boot-starter.version>1.1.21</druid-spring-boot-starter.version>
        <mybatis-plus-boot-starter.version>3.2.0</mybatis-plus-boot-starter.version>
    </properties>

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

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-devtools</artifactId>
            <scope>runtime</scope>
            <optional>true</optional>
        </dependency>
        <dependency>
            <groupId>mysql</groupId>
            <artifactId>mysql-connector-java</artifactId>
            <version>${mysql-connector-java.version}</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-configuration-processor</artifactId>
            <optional>true</optional>
        </dependency>
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <optional>true</optional>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
            <exclusions>
                <exclusion>
                    <groupId>org.junit.vintage</groupId>
                    <artifactId>junit-vintage-engine</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

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

        <!-- https://mvnrepository.com/artifact/com.alibaba/druid-spring-boot-starter -->
        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>druid-spring-boot-starter</artifactId>
            <version>${druid-spring-boot-starter.version}</version>
        </dependency>

        <!-- mybatis-plus-boot-starter -->
        <dependency>
            <groupId>com.baomidou</groupId>
            <artifactId>mybatis-plus-boot-starter</artifactId>
            <version>${mybatis-plus-boot-starter.version}</version>
        </dependency>
    </dependencies>

    ...

</project>

如果不想使用 MyBatis Plus，打算使用 JdbcTemplate 或 MyBatis，可以参考：

Spring Boot - JdbcTemplate

Spring Boot - MyBatis + Druid

application.yml 文件，包括 Druid 数据源、MyBatis Plus 的配置：

spring:
  datasource:
    druid:
      #-- 基本属性
      driver-class-name: com.mysql.jdbc.Driver
      url: jdbc:mysql://127.0.0.1:3306/my?useUnicode=true&characterEncoding=utf8&serverTimezone=UTC&useSSL=true
      username: root
      password: root
      #-- 连接池配置
      initial-size: 5
      min-idle: 5
      max-active: 20
      max-wait: 30000 # 获取连接等待超时的时间
      time-between-eviction-runs-millis: 2000 # 间隔多久才进行一次检测，检测需要关闭的空闲连接，单位是毫秒
      min-evictable-idle-time-millis: 600000 # 一个连接在池中最小生存的时间，单位是毫秒
      max-evictable-idle-time-millis: 900000
      validation-query: select '1'
      test-while-idle: true
      test-on-borrow: false
      test-on-return: false
      pool-prepared-statements: true
      max-open-prepared-statements: 20
      max-pool-prepared-statement-per-connection-size: 20
      #-- 监控统计拦截的 filters，'wall' 用于防火墙
      filters: stat,wall,slf4j
      #-- 监控配置
      web-stat-filter: # WebStatFilter 配置
        enabled: true
        url-pattern: /*
        exclusions: '*.js,*.gif,*.jpg,*.png,*.css,*.ico,/druid/*'
      stat-view-servlet: # StatViewServlet 配置
        enabled: true
        url-pattern: /druid/*
        reset-enable: false
        login-username: admin
        login-password: 123456
#        allow: 127.0.0.1
#        deny: 192.168.1.6
#      aop-patterns: # Spring 监控配置
#      - com.mk.service.*
      filter:
        stat: # 慢 SQL 记录
          slow-sql-millis: 3000
          log-slow-sql: true

#-- MyBatis-Plus
mybatis-plus:
  mapper-locations:
  - classpath:sqlmap/*Mapper.xml # SQL 映射文件的位置
  global-config:
    db-config:
      id-type: AUTO # 数据库的表的主键生成策略
  configuration:
    log-impl: org.apache.ibatis.logging.slf4j.Slf4jImpl # 日志

logback 日志配置：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
    <!-- 定义日志文件的输出路径 -->
    <property name="USER_HOME" value="G:/log" />
    
    <!-- 输出到控制台 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-5level [%-24thread] %logger - %msg%n</pattern>
        </encoder>
    </appender>
    
    <!-- 基于大小以及时间的轮转策略 -->
    <!-- 参考：http://www.logback.cn/04%E7%AC%AC%E5%9B%9B%E7%AB%A0Appenders.html -->
    <appender name="ROLLING" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 要写入文件的名称。如果文件不存在，则新建。 -->
        <file>${USER_HOME}/logback.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${USER_HOME}/%d{yyyyMMdd}/logback-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>20KB</maxFileSize>
            <!-- 最多保留多少数量的归档文件，将会异步删除旧的文件。 -->
            <maxHistory>30</maxHistory>
            <!-- 所有归档文件总的大小。当达到这个大小后，旧的归档文件将会被异步的删除。 -->
            <totalSizeCap>1000MB</totalSizeCap>
        </rollingPolicy>

        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-5level [%-24thread] %logger - %msg%n</pattern>
        </encoder>
    </appender>
    
    <logger name="com.mk.dao" level="DEBUG" ></logger>
    
    <!-- 日志输出级别 -->
    <root level="info">
        <appender-ref ref="ROLLING" />
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

接下来，可以使用 MyBatis Plus 提供的代码生成器生成实体类、DAO、业务层等代码。

实体类：

import com.baomidou.mybatisplus.annotation.TableName;
import com.baomidou.mybatisplus.annotation.IdType;
import com.baomidou.mybatisplus.extension.activerecord.Model;
import com.baomidou.mybatisplus.annotation.TableId;
import java.time.LocalDateTime;
import java.io.Serializable;
import lombok.Data;
import lombok.EqualsAndHashCode;
import lombok.experimental.Accessors;

@Data
@EqualsAndHashCode(callSuper = false)
@Accessors(chain = true)
@TableName("sys_request_log")
public class RequestLog extends Model<RequestLog> {

    private static final long serialVersionUID = 1L;

    /**
     * 编号
     */
    @TableId(value = "id", type = IdType.AUTO)
    private Integer id;

    /**
     * 用户名
     */
    private String username;

    /**
     * 用户代理（客户端）
     */
    private String userAgent;

    /**
     * 请求 URL
     */
    private String requestUrl;

    /**
     * IP
     */
    private String ip;

    /**
     * 请求方法
     */
    private String declaringSignature;

    /**
     * 请求参数
     */
    private String args;

    /**
     * 异常
     */
    private String exception;

    /**
     * 耗时，单位毫秒
     */
    private Integer elapsedTime;

    /**
     * 创建时间
     */
    private LocalDateTime createTime;

    @Override
    protected Serializable pkVal() {
        return this.id;
    }
}

DAO 层（mapper 接口）：

import com.mk.domain.RequestLog;
import com.baomidou.mybatisplus.core.mapper.BaseMapper;

public interface RequestLogMapper extends BaseMapper<RequestLog> {

}

业务层接口及其实现类：

import com.mk.domain.RequestLog;
import com.baomidou.mybatisplus.extension.service.IService;

public interface RequestLogService extends IService<RequestLog> {

    /**
     * <p> 异步保存
     * 
     * @param entity
     */
    void asyncSave(RequestLog entity);
}

import com.mk.domain.RequestLog;
import com.mk.dao.RequestLogMapper;
import com.mk.service.RequestLogService;
import com.baomidou.mybatisplus.extension.service.impl.ServiceImpl;

import org.springframework.scheduling.annotation.Async;
import org.springframework.stereotype.Service;

@Service
public class RequestLogServiceImpl extends ServiceImpl<RequestLogMapper, RequestLog> implements RequestLogService {

    @Async
    @Override
    public void asyncSave(RequestLog entity) {
        super.save(entity);
    }
}

业务层定义了一个 asyncSave 方法，使用 @Async 注解将其标注为异步任务，这个方法调用了父类提供的 save 方法。

AOP 日志处理：

import java.time.LocalDateTime;
import java.util.Arrays;

import javax.servlet.http.HttpServletRequest;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import com.mk.domain.RequestLog;
import com.mk.service.RequestLogService;

@Aspect
@Component
public class LogAspect {

    private static final Logger logger = LoggerFactory.getLogger(LogAspect.class);
    
    @Autowired
    private RequestLogService requestLogService;
    
    private long startTime;
    private RequestLog requestLog;
    
    /**
     * <p> 切点声明
     */
    @Pointcut(value = "execution(* com.mk.controller.*.*(..))")
    public void pointcut() {
        
    }
    
    @Before(value = "pointcut()")
    public void doBefore(JoinPoint joinPoint) {
        ServletRequestAttributes servletRequestAttributes 
            = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = servletRequestAttributes.getRequest();
        
        // 获取请求参数
        String requestUrl = request.getRequestURL().toString();
        String ip = request.getRemoteAddr();
        String userAgent = request.getHeader("User-Agent"); // 用户代理（客户端）
        String declaringSignature = joinPoint.getSignature().getDeclaringTypeName()
                + "." + joinPoint.getSignature().getName();
        String args = (joinPoint.getArgs().length == 0) ? null : Arrays.toString(joinPoint.getArgs());
        
        // 设置请求参数
        this.requestLog = new RequestLog();
        this.requestLog.setUsername("admin");
        this.requestLog.setUserAgent(userAgent);
        this.requestLog.setRequestUrl(requestUrl);
        this.requestLog.setIp(ip);
        this.requestLog.setDeclaringSignature(declaringSignature);
        this.requestLog.setArgs(args);
        this.startTime = System.currentTimeMillis();
    }
    
    @AfterReturning(pointcut = "pointcut()", returning = "returnedValue")
    public void doAfterReturning(Object returnedValue) {
        Integer elapsedTime = (int) (System.currentTimeMillis() - this.startTime);
        this.requestLog.setElapsedTime(elapsedTime);
        this.requestLog.setException(null);
        this.requestLog.setCreateTime(LocalDateTime.now());
        
        logger.info(this.requestLog.toString());
        
        this.requestLogService.asyncSave(this.requestLog); // 异步保存到数据库
    }
    
    @AfterThrowing(pointcut = "pointcut()", throwing = "throwable")
    public void doAfterThrowing(Throwable throwable) {
        this.requestLog.setException(throwable.toString());
        this.requestLog.setCreateTime(LocalDateTime.now());
        
        logger.error(this.requestLog.toString());
        
        this.requestLogService.asyncSave(this.requestLog);
    }
}

控制器，包含两个方法，其中一个会抛出异常，主要是针对 LogAspect.doAfterThrowing(Throwable) 方法：

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class HelloController {

    @GetMapping("/")
    public String login(String username, String password) {
        return username;
    }
    
    @GetMapping("/ex")
    public void exception() {
        int i = 1 / 0;
    }
}

启动类，使用 @MapperScan 注解扫描 mapper 接口；使用 @EnableAsync 注解启动异步任务。

import org.mybatis.spring.annotation.MapperScan;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.scheduling.annotation.EnableAsync;

@SpringBootApplication
@MapperScan(basePackages = { "com.mk.dao" })
@EnableAsync
public class SpringBootAopLogApplication {

    public static void main(String[] args) {
        SpringApplication.run(SpringBootAopLogApplication.class, args);
    }
}

启动项目，分别访问 http://localhost:8080/?username=admin&password=123456 和 http://localhost:8080/ex。

由于 RequestLogServiceImpl.asyncSave(RequestLog) 是一个异步方法，当在 LogAspect 类中调用该方法将请求信息保存到数据库时，并不会在当前线程中执行该方法，而是新建一个线程，并在这个新线程中执行。

这点可以通过控制台输出的日志证实，当用户发起请求时，走的是 http-nio-8080-exec-1，而调用 asyncSave 方法，走的是 task-1 线程：

20:28:00.814 INFO  [http-nio-8080-exec-1    ] com.mk.aspect.LogAspect - RequestLog(id=null, username=admin, userAgent=Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:72.0) Gecko/20100101 Firefox/72.0, requestUrl=http://localhost:8080/, ip=0:0:0:0:0:0:0:1, declaringSignature=com.mk.controller.HelloController.login, args=[admin, 123456], exception=null, elapsedTime=5, createTime=2020-01-24T20:28:00.814)
20:28:00.825 DEBUG [task-1                  ] com.mk.dao.RequestLogMapper.insert - ==>  Preparing: INSERT INTO sys_request_log ( args, create_time, request_url, ip, user_agent, declaring_signature, elapsed_time, username ) VALUES ( ?, ?, ?, ?, ?, ?, ?, ? ) 
20:28:00.827 DEBUG [task-1                  ] com.mk.dao.RequestLogMapper.insert - ==> Parameters: [admin, 123456](String), 2020-01-24T20:28:00.814(LocalDateTime), http://localhost:8080/(String), 0:0:0:0:0:0:0:1(String), Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:72.0) Gecko/20100101 Firefox/72.0(String), com.mk.controller.HelloController.login(String), 5(Integer), admin(String)
20:28:00.970 DEBUG [task-1                  ] com.mk.dao.RequestLogMapper.insert - <==    Updates: 1

查询数据库：

mysql> select * from sys_request_log;
+----+----------+--------------------------------------------------------------------------------+--------------------------+-----------------+---------------------------------------------+-----------------+------------------------------------------+--------------+---------------------+
| id | username | user_agent                                                                     | request_url              | ip              | declaring_signature                         | args            | exception                                | elapsed_time | create_time         |
+----+----------+--------------------------------------------------------------------------------+--------------------------+-----------------+---------------------------------------------+-----------------+------------------------------------------+--------------+---------------------+
| 26 | admin    | Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:72.0) Gecko/20100101 Firefox/72.0 | http://localhost:8080/   | 0:0:0:0:0:0:0:1 | com.mk.controller.HelloController.login     | [admin, 123456] | NULL                                     |            3 | 2020-01-24 20:54:35 |
| 27 | admin    | Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:72.0) Gecko/20100101 Firefox/72.0 | http://localhost:8080/ex | 0:0:0:0:0:0:0:1 | com.mk.controller.HelloController.exception | NULL            | java.lang.ArithmeticException: / by zero |         NULL | 2020-01-24 20:54:36 |
+----+----------+--------------------------------------------------------------------------------+--------------------------+-----------------+---------------------------------------------+-----------------+------------------------------------------+--------------+---------------------+
2 rows in set (0.00 sec)

参考

Spring Boot 2.X(八)：Spring AOP 实现简单的日志切面

Spring Boot AOP记录用户操作日志

Spring Boot—(4)SpringBoot异步处理任务