Spring Boot 2.x 教程系列 | AOP 切面统一打印请求日志最佳实践

文章首发于个人网站 www.exception.site/springboot

本节中，您将学习如何在 Spring Boot 中使用 AOP 切面统一处理请求日志，打印进出参相关参数。

注意：本节中 AOP 切面统一处理请求日志已被博主用于生产环境中，所以您在生产环境中添加它时，仅需对出入参稍加调整即可。

一、先看看日志输出效果

可以看到，每个对于每个请求，开始与结束一目了然，并且打印了以下参数：

• URL : 请求接口地址；
• HTTP Method : 请求的方法，是 POST , GET , 还是 DELETE 等；
• Class Method : 对应 Controller 的全路径以及调用的哪个方法;
• IP : 请求 IP 地址；
• Request Args : 请求入参，以 JSON 格式输出；
• Response Args : 响应出参，以 JSON 格式输出；
• Time-Consuming : 请求耗时；

效果应该还不错吧！接下来就让我们一步一步去实现该功能, 首先， 新建一个 Spring Boot Web 项目 。

二、添加 Maven 依赖

在项目 pom.xml 文件中添加依赖：

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

<!-- 用于日志切面中，以 json 格式打印出入参 -->
<dependency>
    <groupId>com.alibaba</groupId>
    <artifactId>fastjson</artifactId>
    <version>1.2.55</version>
</dependency>
复制代码

三、配置 AOP 切面

在配置 AOP 切面之前，我们需要了解下 aspectj 相关注解的作用：

• @Aspect ：声明该类为一个注解类；
• @Pointcut ：定义一个切点，后面跟随一个表达式，表达式可以定义为某个 package 下的方法，也可以是自定义注解等；
• 切点定义好后，就是围绕这个切点做文章了：
  • @Before : 在切点之前，织入相关代码；
  • @After : 在切点之后，织入相关代码;
  • @AfterReturning : 在切点返回内容后，织入相关代码，一般用于对返回值做加的场景；
  • @AfterThrowing : 用来处理当织入的代码抛出异常后的逻辑处理;
  • @Around : 在切入点前后织入代码，并且可以自由的控制何时执行切点；

接下来，定义一个 WebLogAspect.java 切面类，代码如下：

package site.exception.springbootaopwebrequest.aspect;

import com.alibaba.fastjson.JSONObject;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;

/**
 * @author www.exception.site (exception 教程网)
 * @date 2019/2/12
 * @time 14:03
 * @discription
 **/
@Aspect
@Component
public class WebLogAspect {

    private final static Logger logger = LoggerFactory.getLogger(WebLogAspect.class);

    /** 以 controller 包下定义的所有请求为切入点 */
    @Pointcut("execution(public * site.exception.springbootaopwebrequest.controller..*.*(..))")
    public void webLog() {}

    /**
     * 在切点之前织入
     * @param joinPoint
     * @throws Throwable
     */
    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) throws Throwable {
        // 开始打印请求日志
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();

        // 打印请求相关参数
        logger.info("========================================== Start ==========================================");
        // 打印请求 url
        logger.info("URL            : {}", request.getRequestURL().toString());
        // 打印 Http method
        logger.info("HTTP Method    : {}", request.getMethod());
        // 打印调用 controller 的全路径以及执行方法
        logger.info("Class Method   : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
        // 打印请求的 IP
        logger.info("IP             : {}", request.getRemoteAddr());
        // 打印请求入参
        logger.info("Request Args   : {}", JSONObject.toJSONString(joinPoint.getArgs()));
    }

    /**
     * 在切点之后织入
     * @throws Throwable
     */
    @After("webLog()")
    public void doAfter() throws Throwable {
        logger.info("=========================================== End ===========================================");
        // 每个请求之间空一行
        logger.info("");
    }

    /**
     * 环绕
     * @param proceedingJoinPoint
     * @return
     * @throws Throwable
     */
    @Around("webLog()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object result = proceedingJoinPoint.proceed();
        // 打印出参
        logger.info("Response Args  : {}", JSONObject.toJSONString(result));
        // 执行耗时
        logger.info("Time-Consuming : {} ms", System.currentTimeMillis() - startTime);
        return result;
    }

}

复制代码

我们通过 @Aspect 声明了 WebLogAspect.java 为切面类，之后，通过 @Pointcut 定义了打印请求日志的切点，切点为 site.exception.springbootaopwebrequest.controller 包下所有的请求接口。

切点定义好后，我们通过 @Before 在切点之前打印请求的相关参数，通过 @Around 打印了请求接口的耗时时间，最后通过 @After 做了请求的收尾工作。

到这里，切面相关的代码就完成了！

三、定义测试接口，看下效果

定义一个以 POST 方式提交的测试接口：

package site.exception.springbootaopwebrequest.controller;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RestController;
import site.exception.springbootaopwebrequest.entity.User;

/**
 * @author www.exception.site (exception 教程网)
 * @date 2019/2/16
 * @time 21:03
 * @discription
 **/
@RestController
public class UserController {

    private final static Logger logger = LoggerFactory.getLogger(UserController.class);

    /**
     * 定义一个创建用户的接口
     * @param user
     * @return
     */
    @PostMapping("/user")
    public User createUser(@RequestBody User user) {
        logger.info("create user ...");
        return user;
    }

}

复制代码

User.java:

package site.exception.springbootaopwebrequest.entity;

import java.io.Serializable;
import java.util.Date;

/**
 * @author www.exception.site (exception 教程网)
 * @date 2019/2/16
 * @time 21:00
 * @discription
 **/
public class User implements Serializable {
    /**
     * 用户名
     */
    private String username;
    /**
     * 密码
     */
    private String password;
    /**
     * 创建时间
     */
    private Date createTime;

    public String getUsername() {
        return username;
    }

    public void setUsername(String username) {
        this.username = username;
    }

    public String getPassword() {
        return password;
    }

    public void setPassword(String password) {
        this.password = password;
    }

    public Date getCreateTime() {
        return createTime;
    }

    public void setCreateTime(Date createTime) {
        this.createTime = createTime;
    }
}

复制代码

最后，通过 Postman 请求 /user 接口：

看看控制台输出效果：

2019-02-20 13:29:15.026  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : ========================================== Start ==========================================
2019-02-20 13:29:15.027  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : URL            : http://localhost:8080/user
2019-02-20 13:29:15.028  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : HTTP Method    : POST
2019-02-20 13:29:15.030  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : Class Method   : site.exception.springbootaopwebrequest.controller.UserController.createUser
2019-02-20 13:29:15.030  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : IP             : 0:0:0:0:0:0:0:1
2019-02-20 13:29:15.131  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : Request Args   : [{"password":"123456","username":"张三"}]
2019-02-20 13:29:15.136  INFO 2884 --- [nio-8080-exec-2] s.e.s.controller.UserController          : create user ...
2019-02-20 13:29:15.136  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : Response Args  : {"password":"123456","username":"张三"}
2019-02-20 13:29:15.136  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : Time-Consuming : 110 ms
2019-02-20 13:29:15.137  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : =========================================== End ===========================================
2019-02-20 13:29:15.137  INFO 2884 --- [nio-8080-exec-2] s.e.s.aspect.WebLogAspect                : 
复制代码

OK, 大功告成!