Spring Boot配置AOP打印日志的全过程

前言

在项目开发中，日志系统是必不可少的，用aop在web的请求做入参和出参的参数打印，同时对异常进行日志打印，避免重复的手写日志，完整案例见文末源码。

一、spring aop

aop(aspect-oriented programming，面向切面编程)，它利用一种"横切"的技术，将那些多个类的共同行为封装到一个可重用的模块。便于减少系统的重复代码，降低模块之间的耦合度，并有利于未来的可操作性和可维护性。

aop中有以下概念：

• aspect（切面）：声明类似于java中的类声明，在aspect中会包含一些pointcut及相应的advice。
• joint point（连接点）：表示在程序中明确定义的点。包括方法的调用、对类成员的访问等。
• pointcut（切入点）：表示一个组joint point，如方法名、参数类型、返回类型等等。
• advice（通知）：advice定义了在pointcut里面定义的程序点具体要做的操作，它通过(before、around、after(return、throw)、finally来区别实在每个joint point之前、之后还是执行 前后要调用的代码。
• before：在执行方法前调用advice，比如请求接口之前的登录验证。
• around：在执行方法前后调用advice，这是最常用的方法。
• after：在执行方法后调用advice，after、return是方法正常返回后调用，after\throw是方法抛出异常后调用。
• finally：方法调用后执行advice，无论是否抛出异常还是正常返回。
• aop proxy：aop proxy也是java对象，是由aop框架创建，用来完成上述动作，aop对象通常可以通过jdk dynamic proxy完成，或者使用cglib完成。
• weaving：实现上述切面编程的代码织入，可以在编译时刻，也可以在运行时刻，spring和其它大多数java框架都是在运行时刻生成代理。

二、项目示例

当然，在使用该案例之前，如果需要了解日志配置相关，可参考 springboot 异步输出 logback 日志， 本文就不再概述了。

2.1 在pom引入依赖

<dependencies>
 <dependency>
 <groupid>org.springframework.boot</groupid>
 <artifactid>spring-boot-starter-web</artifactid>
 </dependency>

 <dependency>
 <groupid>org.springframework.boot</groupid>
 <artifactid>spring-boot-starter-aop</artifactid>
 </dependency>
 <!-- 分析客户端信息的工具类-->
 <dependency>
 <groupid>eu.bitwalker</groupid>
 <artifactid>useragentutils</artifactid>
 <version>1.20</version>
 </dependency>
 <!-- lombok -->
 <dependency>
 <groupid>org.projectlombok</groupid>
 <artifactid>lombok</artifactid>
 <scope>1.8.4</scope>
 </dependency>
</dependencies>

2.2 controller 切面：weblogaspect

@aspect
@component
@slf4j
public class weblogaspect {

 /**
 * 进入方法时间戳
 */
 private long starttime;
 /**
 * 方法结束时间戳(计时)
 */
 private long endtime;

 public weblogaspect() {
 }


 /**
 * 定义请求日志切入点，其切入点表达式有多种匹配方式,这里是指定路径
 */
 @pointcut("execution(public * cn.van.log.aop.controller.*.*(..))")
 public void weblogpointcut() {
 }

 /**
 * 前置通知：
 * 1. 在执行目标方法之前执行，比如请求接口之前的登录验证;
 * 2. 在前置通知中设置请求日志信息，如开始时间，请求参数，注解内容等
 *
 * @param joinpoint
 * @throws throwable
 */
 @before("weblogpointcut()")
 public void dobefore(joinpoint joinpoint) {

 // 接收到请求，记录请求内容
 servletrequestattributes attributes = (servletrequestattributes) requestcontextholder.getrequestattributes();
 httpservletrequest request = attributes.getrequest();
 //获取请求头中的user-agent
 useragent useragent = useragent.parseuseragentstring(request.getheader("user-agent"));
 //打印请求的内容
 starttime = system.currenttimemillis();
 log.info("请求开始时间：{}" + localdatetime.now());
 log.info("请求url : {}" + request.getrequesturl().tostring());
 log.info("请求方式 : {}" + request.getmethod());
 log.info("请求ip : {}" + request.getremoteaddr());
 log.info("请求方法 : " + joinpoint.getsignature().getdeclaringtypename() + "." + joinpoint.getsignature().getname());
 log.info("请求参数 : {}" + arrays.tostring(joinpoint.getargs()));
 // 系统信息
 log.info("浏览器：{}", useragent.getbrowser().tostring());
 log.info("浏览器版本：{}", useragent.getbrowserversion());
 log.info("操作系统: {}", useragent.getoperatingsystem().tostring());
 }

 /**
 * 返回通知：
 * 1. 在目标方法正常结束之后执行
 * 1. 在返回通知中补充请求日志信息，如返回时间，方法耗时，返回值，并且保存日志信息
 *
 * @param ret
 * @throws throwable
 */
 @afterreturning(returning = "ret", pointcut = "weblogpointcut()")
 public void doafterreturning(object ret) throws throwable {
 endtime = system.currenttimemillis();
 log.info("请求结束时间：{}" + localdatetime.now());
 log.info("请求耗时：{}" + (endtime - starttime));
 // 处理完请求，返回内容
 log.info("请求返回 : {}" + ret);
 }

 /**
 * 异常通知：
 * 1. 在目标方法非正常结束，发生异常或者抛出异常时执行
 * 1. 在异常通知中设置异常信息，并将其保存
 *
 * @param throwable
 */
 @afterthrowing(value = "weblogpointcut()", throwing = "throwable")
 public void doafterthrowing(throwable throwable) {
 // 保存异常日志记录
 log.error("发生异常时间：{}" + localdatetime.now());
 log.error("抛出异常：{}" + throwable.getmessage());
 }
}

2.3 编写测试

@restcontroller
@requestmapping("/log")
public class logbackcontroller {

 /**
 * 测试正常请求
 * @param msg
 * @return
 */
 @getmapping("/{msg}")
 public string getmsg(@pathvariable string msg) {
 return "request msg : " + msg;
 }

 /**
 * 测试抛异常
 * @return
 */
 @getmapping("/test")
 public string getexception(){
 // 故意造出一个异常
 integer.parseint("abc123");
 return "success";
 }
}

2.4 @before和@afterreturning部分也可使用以下代码替代

 /**
 * 在执行方法前后调用advice，这是最常用的方法，相当于@before和@afterreturning全部做的事儿
 * @param pjp
 * @return
 * @throws throwable
 */
 @around("weblogpointcut()")
 public object doaround(proceedingjoinpoint pjp) throws throwable {
 // 接收到请求，记录请求内容
 servletrequestattributes attributes = (servletrequestattributes) requestcontextholder.getrequestattributes();
 httpservletrequest request = attributes.getrequest();
 //获取请求头中的user-agent
 useragent useragent = useragent.parseuseragentstring(request.getheader("user-agent"));
 //打印请求的内容
 starttime = system.currenttimemillis();
 log.info("请求url : {}" , request.getrequesturl().tostring());
 log.info("请求方式 : {}" , request.getmethod());
 log.info("请求ip : {}" , request.getremoteaddr());
 log.info("请求方法 : " , pjp.getsignature().getdeclaringtypename() , "." , pjp.getsignature().getname());
 log.info("请求参数 : {}" , arrays.tostring(pjp.getargs()));
 // 系统信息
 log.info("浏览器：{}", useragent.getbrowser().tostring());
 log.info("浏览器版本：{}",useragent.getbrowserversion());
 log.info("操作系统: {}", useragent.getoperatingsystem().tostring());
 // pjp.proceed()：当我们执行完切面代码之后，还有继续处理业务相关的代码。proceed()方法会继续执行业务代码，并且其返回值，就是业务处理完成之后的返回值。
 object ret = pjp.proceed();
 log.info("请求结束时间："+ localdatetime.now());
 log.info("请求耗时：{}" , (system.currenttimemillis() - starttime));
 // 处理完请求，返回内容
 log.info("请求返回 : " , ret);
 return ret;
 }

三、 测试

3.1 请求入口logbackcontroller.java

@restcontroller
@requestmapping("/log")
public class logbackcontroller {

 /**
 * 测试正常请求
 * @param msg
 * @return
 */
 @getmapping("/normal/{msg}")
 public string getmsg(@pathvariable string msg) {
 return msg;
 }

 /**
 * 测试抛异常
 * @return
 */
 @getmapping("/exception/{msg}")
 public string getexception(@pathvariable string msg){
 // 故意造出一个异常
 integer.parseint("abc123");
 return msg;
 }
}

3.2 测试正常请求

打开浏览器，访问http://localhost:8082/log/normal/hello

日志打印如下：

[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [65] [info ] 请求开始时间：2019-02-24t22:37:50.892
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [66] [info ] 请求url :
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [67] [info ] 请求方式 : get
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [68] [info ] 请求ip : 0:0:0:0:0:0:0:1
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [69] [info ] 请求方法 :
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [70] [info ] 请求参数 : [hello]
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [72] [info ] 浏览器：chrome
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [73] [info ] 浏览器版本：76.0.3809.100
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [74] [info ] 操作系统: mac_os_x
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [88] [info ] 请求结束时间：2019-02-24t22:37:50.901
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [89] [info ] 请求耗时：14
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-1] [91] [info ] 请求返回 : hello

3.3 测试异常情况

访问：http://localhost:8082/log/exception/hello

[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [65] [info ] 请求开始时间：2019-02-24t22:39:57.728
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [66] [info ] 请求url :
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [67] [info ] 请求方式 : get
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [68] [info ] 请求ip : 0:0:0:0:0:0:0:1
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [69] [info ] 请求方法 :
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [70] [info ] 请求参数 : [hello]
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [72] [info ] 浏览器：chrome
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [73] [info ] 浏览器版本：76.0.3809.100
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [74] [info ] 操作系统: mac_os_x
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [104] [error] 发生异常时间：2019-02-24t22:39:57.731
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.weblogaspect] [http-nio-8082-exec-9] [105] [error] 抛出异常：for input string: "abc123"
[2019-02-24 22:39:57.057] [org.apache.juli.logging.directjdklog] [http-nio-8082-exec-9] [175] [error] servlet.service() for servlet [dispatcherservlet] in context with path [] threw exception [request processing failed; nested exception is java.lang.numberformatexception: for input string: "abc123"] with root cause
java.lang.numberformatexception: for input string: "abc123"

四、源码

4.1 示例代码

github 示例代码

总结

以上就是这篇文章的全部内容了，希望本文的内容对大家的学习或者工作具有一定的参考学习价值，谢谢大家对的支持。