引言
上一文走进Java接口测试之日志框架Logback中，介绍了目前接口测试框架中常见的 logback 日志框架的整合知识。在很多时候，我们在开发一个测试框架时，不管出于何种考虑，比如是审计要求，还是调试的角度，一般都会有个全局记录日志的模块功能。此模块一般上会记录每个对数据有进行变更的操作记录，若是在web测试平台上，还会记录请求的url,请求的IP,及当前的操作人，操作的方法说明等等。在很多时候，我们需要记录请求的参数信息时，通常是利用拦截器、过滤器或者 AOP 等来进行统一拦截。
本文主要来说一说如何利用AOP实现统一的日志记录。
什么是AOP？
AOP全称：
AspectOrientedProgramming。是一种面向切面编程的，利用预编译方式和运行期动态代理实现程序功能统一的一种技术。它也是Spring 很重要的一部分，和 IOC一样重要。利用AOP可以很好的对业务逻辑的各个部分进行隔离，从而使得业务逻辑各部分之间的耦合度降低，提高程序的可重用性，同时提高了开发的效率。
简单来说，就是 AOP 可以在既有的程序基础上，在无代码嵌入前提下完成对相关业务的处理，业务方可以只关注自身业务的逻辑，而无需关系一些和业务无关的事项，比如最常见的日志、事务、权限检验、性能统计、统一异常处理等等。
AOP基本概念
以下简单的说明下：
- 切面（Aspect）：切面是一个关注点的模块化，这个关注点可能是横切多个对象；
- 连接点（Join Point）：连接点是指在程序执行过程中某个特定的点，比如某方法调用的时候或者处理异常的时候；
- 通知（Advice）：指在切面的某个特定的连接点上执行的动作。Spring切面可以应用5中通知：
- 前置通知（Before）:在目标方法或者说连接点被调用前执行的通知；
- 后置通知（After）：指在某个连接点完成后执行的通知；
- 返回通知（After-returning）：指在某个连接点成功执行之后执行的通知；
- 异常通知（After-throwing）：指在方法抛出异常后执行的通知；
- 环绕通知（Around）：指包围一个连接点通知，在被通知的方法调用之前和之后执行自定义的方法。
- 切点（Pointcut）：指匹配连接点的断言。通知与一个切入点表达式关联，并在满足这个切入的连接点上运行，例如：当执行某个特定的名称的方法。
- 引入（Introduction）：引入也被称为内部类型声明，声明额外的方法或者某个类型的字段。
- 目标对象（Target Object）：目标对象是被一个或者多个切面所通知的对象。
- AOP代理（AOP Proxy）：AOP代理是指AOP框架创建的对对象，用来实现切面契约（包括通知方法等功能）
- 织入（Wearving）：指把切面连接到其他应用出程序类型或者对象上，并创建一个被通知的对象。或者说形成代理对象的方法的过程。
以下这张图，对以上部分概念进行简单介绍：
代理机制
Spring 的 AOP 的动态代理实现机制有两种，分别是：JDK 动态代理和CGLib 动态代理。简单介绍下两种代理机制。
JDK动态代理
JDK 动态代理是面向接口的代理模式，如果被代理目标没有接口那么Spring也无能为力，Spring 通过 java 的反射机制生产被代理接口的新的匿名实现类，重写了其中AOP的增强方法。
CGLib动态代理
CGLib 是一个强大、高性能的 Code 生产类库，可以实现运行期动态扩展java类，Spring 在运行期间通过 CGlib 继承要被动态代理的类，重写父类的方法，实现AOP面向切面编程。
两者对比：
- JDK动态代理是面向接口，在创建代理实现类时比CGLib要快，创建代理速度快。而且JDK动态代理只能对实现了接口的类生成代理，而不能针对类。
- CGLib动态代理是通过字节码底层继承要代理类来实现（如果被代理类被final关键字所修饰，那么抱歉会失败），在创建代理这一块没有JDK动态代理快，但是运行速度比JDK动态代理要快。
至于相关原理，大家自行谷歌下~
切入点指示符介绍
为了能够灵活定义切入点位置，Spring AOP 提供了多种切入点指示符。以下简单的介绍下。
- execution：匹配执行方法的连接点
可以从上图中，看见切入点指示符 execution的 语法结构为：execution（modifiers-pattern? ret-type-pattern declaring-type-pattern? name-pattern（param-pattern） throws-pattern?）。这也是最常使用的一个指示符了。
- within：用于匹配指定类型内的方法执行；
- this：用于匹配当前AOP代理对象类型的执行方法；注意是AOP代理对象的类型匹配，这样就可能包括引入接口也类型匹配；
- target：用于匹配当前目标对象类型的执行方法；注意是目标对象的类型匹配，这样就不包括引入接口也类型匹配；
- args：用于匹配当前执行的方法传入的参数为指定类型的执行方法；
- @within：用于匹配所以持有指定注解类型内的方法；
- @target：用于匹配当前目标对象类型的执行方法，其中目标对象持有指定的注解；
- @args：用于匹配当前执行的方法传入的参数持有指定注解的执行；
- @annotation：用于匹配当前执行方法持有指定注解的方法；
- bean：Spring AOP扩展的，AspectJ没有对于指示符，用于匹配特定名称的Bean对象的执行方法；
- reference pointcut：表示引用其他命名切入点，只有@ApectJ风格支持，Schema风格不支持。
对于相关的语法和使用，大家可行谷歌搜索，这里就不多加阐述了。
MDC requestUUID，一种多线程下日志管理实践方式
MDC（ MappedDiagnosticContext，映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。某些应用程序采用多线程的方式来处理多个用户的请求。在一个用户的使用过程中，可能有多个不同的线程来进行处理。典型的例子是 Web 应用服务器。当用户访问某个页面时，应用服务器可能会创建一个新的线程来处理该请求，也可能从线程池中复用已有的线程。在一个用户的会话存续期间，可能有多个线程处理过该用户的请求。这使得比较难以区分不同用户所对应的日志。当需要追踪某个用户在系统中的相关日志记录时，就会变得很麻烦。
一种解决的办法是采用自定义的日志格式，把用户的信息采用某种方式编码在日志记录中。这种方式的问题在于要求在每个使用日志记录器的类中，都可以访问到用户相关的信息。这样才可能在记录日志时使用。这样的条件通常是比较难以满足的。MDC 的作用是解决这个问题。
MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。
至于相关原理及具体使用，大家可自行谷歌下~
统一日志记录
介绍完相关知识后，我们开始来使用 AOP 实现统一的日志记录功能。
加入Aop依赖
1. <dependencies>
2. <dependency>
3. <groupId>org.springframework.boot</groupId>
4. <artifactId>spring-boot-starter</artifactId>
5. </dependency>
6. <dependency>
7. <groupId>org.springframework.boot</groupId>
8. <artifactId>spring-boot-starter-aop</artifactId>
9. </dependency>
10. <dependency>
11. <groupId>org.springframework.boot</groupId>
12. <artifactId>spring-boot-starter-web</artifactId>
13. </dependency>
14. <dependency>
15. <groupId>org.springframework.boot</groupId>
16. <artifactId>spring-boot-starter-test</artifactId>
17. <scope>test</scope>
18. </dependency>
19. <dependency>
20. <groupId>org.springframework.boot</groupId>
21. <artifactId>spring-boot-autoconfigure</artifactId>
22. </dependency>
23.
24. <!--引入Json序列化库-->
25. <dependency>
26. <groupId>com.alibaba</groupId>
27. <artifactId>fastjson</artifactId>
28. <version>1.2.47</version>
29. </dependency>
30.
31. <!--引入效率插件-->
32. <dependency>
33. <groupId>org.projectlombok</groupId>
34. <artifactId>lombok</artifactId>
35. <version>1.18.2</version>
36. </dependency>自定义拦截器 logback requestUUID
1. /**
2. * 描述: 自定义拦截器 logback requestUUID
3. *
4. * @author zuozewei
5. * @create 2018-12-30 12:15
6. **/
7.
8. @Slf4j
9. public class ControllerInterceptor extends HandlerInterceptorAdapter {
10.
11. //在请求处理之前回调方法
12. @Override
13. public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
14.
15. String requestUUID = MDC.get("requestUUID");
16. if (requestUUID == null || "".equals(requestUUID)) {
17. String uuid = UUID.randomUUID().toString();
18. uuid = uuid.replaceAll("-", "").toUpperCase();
19. MDC.put("requestUUID", uuid);
20. log.info("ControllerInterceptor preHandle 在请求处理之前生成 logback requestUUID:{}", uuid);
21. }
22.
23. return true;// 只有返回true才会继续向下执行，返回false取消当前请求
24. }
25.
26. //请求处理之后回调方法
27. @Override
28. public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
29. /* 线程结束后需要清除,否则当前线程会一直占用这个requestId值 */
30. log.info("ControllerInterceptor postHandle 请求处理之后清除 logback MDC requestUUID");
31. MDC.remove("requestUUID");
32. }
33.
34. //整个请求处理完毕回调方法
35. @Override
36. public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
37. /*整个请求线程结束后需要清除,否则当前线程会一直占用这个requestId值 */
38. log.info("ControllerInterceptor afterCompletion 整个请求处理完毕清除 logback MDC requestUUID");
39. MDC.clear();
40.
41. }
42. }对日志进行格式化,时候用到 logback-spring.xml配置
1. <!--对日志进行格式化-->
2. <property name="LOG_MSG" value="- | [%X{requestUUID}] | [%d{yyyyMMdd HH:mm:ss.SSS}] | [%level] | [${HOSTNAME}] | [%thread] | [%logger{36}] | --> %msg|%n "/>拦截器配置
1. /**
2. * 描述:拦截器配置
3. *
4. * @author zuozewei
5. * @create 2018-12-30 12:54
6. **/
7. @Configuration
8. public class MyWebMvcConfigurer extends WebMvcConfigurerAdapter {
9.
10. @Override
11. public void addInterceptors(InterceptorRegistry registry) {
12.
13. /**
14. * 多个拦截器组成一个拦截器链
15. * addPathPatterns 用于添加拦截规则
16. * excludePathPatterns 用于排除拦截
17. */
18. registry.addInterceptor(new ControllerInterceptor()).addPathPatterns("/**");
19. super.addInterceptors(registry);
20. }
21. }自定义日志注解
1. /**
2. * 日志注解类
3. * @author zuozewei
4. *
5. */
6. @Target({ElementType.TYPE, ElementType.METHOD})
7. @Retention(RetentionPolicy.RUNTIME)
8. public @interface Log {
9. /**
10. * 日志描述，这里使用了@AliasFor 别名。spring提供的
11. * @return
12. */
13. @AliasFor("desc")
14. String value() default "";
15.
16. /**
17. * 日志描述
18. * @return
19. */
20. @AliasFor("value")
21. String desc() default "";
22.
23. /**
24. * 是否忽略
25. * @return
26. */
27. boolean ignore() default false;
28. }TIPS：熟悉Spring常用注解类的通信，对 @AliasFor 应该不陌生。它是Spring 提供的一个注解，主要是给注解的属性起名别的。让使用注解时，更加的容易理解（比如给 value 属性起别名）。一般上是配对别名。由于是 Spring 框架提供的，所以要使其生效，可以使用 AnnotationUtils.synthesizeAnnotation或者 AnnotationUtils.getAnnotation方法调用获取注解
日志切面
1. /**
2. * 日志切面类
3. * Created by zuozewei on 2018/12/12.
4. */
5. @Aspect //申明一个切面
6. @Component
7. public class LogAspect {
8.
9. private static final Logger log = LoggerFactory.getLogger(LogAspect.class);
10. private static final String dateFormat = "yyyy-MM-dd HH:mm:ss";
11. private static final String STRING_START = "\n>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>\n";
12. private static final String STRING_END = "\n<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n";
13.
14. //设置切入点
15. @Pointcut("within(@org.springframework.web.bind.annotation.RestController *)")
16. public void serviceLog() {
17. }
18.
19. /**
20. * 切换方法，记录日志
21. * @param joinPoint
22. * @return
23. * @throws Throwable
24. */
25. @Around("serviceLog()")
26. public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
27. MethodSignature signature = (MethodSignature) joinPoint.getSignature();
28. Method method = signature.getMethod();
29. Class<?> targetClass = method.getDeclaringClass();
30.
31. StringBuffer classAndMethod = new StringBuffer();
32.
33. Log classAnnotation = targetClass.getAnnotation(Log.class);
34. Log methodAnnotation = method.getAnnotation(Log.class);
35.
36. if (classAnnotation != null) {
37. if (classAnnotation.ignore()) {
38. return joinPoint.proceed();
39. }
40. classAndMethod.append(classAnnotation.value()).append("-");
41. }
42.
43. if (methodAnnotation != null) {
44. if (methodAnnotation.ignore()) {
45. return joinPoint.proceed();
46. }
47. classAndMethod.append(methodAnnotation.value());
48. }
49.
50. String target = targetClass.getName() + "#" + method.getName();
51.
52. String params = null;
53. params = JSONObject.toJSONStringWithDateFormat(joinPoint.getArgs(), dateFormat, SerializerFeature.WriteMapNullValue);
54.
55. log.info(STRING_START + "{} 开始调用--> {} 参数:{}", classAndMethod.toString(), target, params);
56.
57. long start = System.currentTimeMillis();
58. Object result = joinPoint.proceed();
59. long timeConsuming = System.currentTimeMillis() - start;
60.
61. log.info("\n{} 调用结束<-- {} 返回值:{} 耗时:{}ms" + STRING_END, classAndMethod.toString(), target, JSONObject.toJSONStringWithDateFormat(result, dateFormat, SerializerFeature.WriteMapNullValue), timeConsuming);
62. return result;
63. }
64. }配置启动
启动类加入注解 @EnableAspectJAutoProxy，生效注解。另一说法，默认引入pom依赖就是默认开启的。无所谓，加了就是了，加上总之是个好习惯。
1. @SpringBootApplication
2. @EnableAspectJAutoProxy
3. @Slf4j
4. public class LogbackdemoApplication {
5.
6. public static void main(String[] args) {
7. SpringApplication.run(LogbackdemoApplication.class, args);
8. log.info("程序启动！");
9. }
10. }控制层
1. /**
2. * aop统一异常示例
3. * @author oKong
4. *
5. */
6. @RestController
7. public class DemoController {
8. /**
9. * 简单方法示例
10. * @param hello
11. * @return
12. */
13. @RequestMapping("/aop")
14. @Log(value="请求了aopDemo方法")
15. public String aopDemo(String hello) {
16. return "请求参数为：" + hello;
17. }
18.
19. /**
20. * 不拦截日志示例
21. * @param hello
22. * @return
23. */
24. @RequestMapping("/notaop")
25. @Log(ignore=true)
26. public String notAopDemo(String hello) {
27. return "此方法不记录日志，请求参数为：" + hello;
28. }
29. }测试 logback
测试统一拦截日志
浏览器访问：http://127.0.0.1:8888/aop/?content=”我是测试内容”
日志前面的 8B7B6968FB9A45BD8A3681AF3B123212 就是通过logback 的 MDC 做到的
1. >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2. 请求了aopDemo方法 开始调用--> com.zuozewei.logbackdemo.controller.DemoController#aopDemo 参数:["”我是测试内容”"]|
3. - | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.913] | [INFO] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.l.controller.DemoController] | --> 请求参数：content:”我是测试内容”|
4. - | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.913] | [WARN] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.l.controller.DemoController] | --> 请求参数：content:”我是测试内容”|
5. - | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.913] | [ERROR] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.l.controller.DemoController] | --> 请求参数：content:”我是测试内容”|
6. - | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.914] | [INFO] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.logbackdemo.aspect.LogAspect] | -->
7. 请求了aopDemo方法 调用结束<-- com.zuozewei.logbackdemo.controller.DemoController#aopDemo 返回值:"2018-12-30T12:12:28.913,content:”我是测试内容”" 耗时:56ms
8. <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<从上图可以看到，日志输出内容元素具体如下：
- requestUUID：一次请求是唯一的
- 时间日期：精确到毫秒
- 日志级别：ERROR, WARN, INFO, DEBUG or TRACE
- 主机名：
- 进程ID：
- 类路径：
- 分隔符： --> 标识实际日志的开始
- 日志内容：
日志切面的响应：
1. 请求了aopDemo方法 开始调用--> com.zuozewei.logbackdemo.controller.DemoController#aopDemo 参数:["”我是测试内容”"]|
2. com.zuozewei.logbackdemo.controller.DemoController#aopDemo 返回值:"2018-12-30T12:12:28.913,content:”我是测试内容”" 耗时:56ms测试忽略拦截日志
浏览器访问：http://127.0.0.1:8888/notaop/?content=”我是测试内容”
1. - | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.749] | [INFO] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.aspect.ControllerInterceptor] | --> ControllerInterceptor preHandle 在请求处理之前生成 logback requestUUID:E5FB9C1D66514C2783B8E4C8024562F4|
2. - | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.753] | [INFO] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.controller.DemoController] | --> 请求参数：content:”不记录日志“|
3. - | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.753] | [WARN] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.controller.DemoController] | --> 请求参数：content:”不记录日志“|
4. - | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.754] | [ERROR] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.controller.DemoController] | --> 请求参数：content:”不记录日志“|
5. - | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.794] | [INFO] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.aspect.ControllerInterceptor] | --> ControllerInterceptor postHandle 请求处理之后清除 logback MDC requestUUID|
从上面看到日志切面被忽略。工程目录
总结
本文主要是简单介绍了利用 AOP 实现统一的请求日志记录功能。本示例未演示日志入库功能，后续再实现。在实际测试开发过程中，一般上都是将日志保存进行异步化后进行入库处理的，这点需要注意，日志记录不能影响正常的方法请求，若是同步的，会本末倒置的。
本文代码：
https://github.com/7DGroup/Java-API-Test-Examples
