走进Java接口测试之AOP统一日志记录

高楼Zee

发布于 2019-07-17 17:58:12

2.3K0

发布于 2019-07-17 17:58:12

文章被收录于专栏：7DGroup

引言

上一文走进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依赖

<dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-autoconfigure</artifactId>
        </dependency>

        <!--引入Json序列化库-->
        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>fastjson</artifactId>
            <version>1.2.47</version>
        </dependency>

        <!--引入效率插件-->
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <version>1.18.2</version>
        </dependency>

自定义拦截器 logback requestUUID

/**
 * 描述: 自定义拦截器 logback requestUUID
 *
 * @author zuozewei
 * @create 2018-12-30 12:15
 **/

@Slf4j
public class ControllerInterceptor extends HandlerInterceptorAdapter {

    //在请求处理之前回调方法
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {

        String requestUUID = MDC.get("requestUUID");
        if (requestUUID == null || "".equals(requestUUID)) {
            String uuid = UUID.randomUUID().toString();
            uuid = uuid.replaceAll("-", "").toUpperCase();
            MDC.put("requestUUID", uuid);
            log.info("ControllerInterceptor preHandle 在请求处理之前生成 logback requestUUID:{}", uuid);
        }

        return true;// 只有返回true才会继续向下执行，返回false取消当前请求
    }

    //请求处理之后回调方法
    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        /* 线程结束后需要清除,否则当前线程会一直占用这个requestId值 */
        log.info("ControllerInterceptor postHandle 请求处理之后清除 logback MDC requestUUID");
        MDC.remove("requestUUID");
    }

    //整个请求处理完毕回调方法
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        /*整个请求线程结束后需要清除,否则当前线程会一直占用这个requestId值 */
        log.info("ControllerInterceptor afterCompletion 整个请求处理完毕清除 logback MDC requestUUID");
        MDC.clear();

    }
}

对日志进行格式化,时候用到 logback-spring.xml配置

<!--对日志进行格式化-->
    <property name="LOG_MSG" value="- | [%X{requestUUID}] | [%d{yyyyMMdd HH:mm:ss.SSS}] | [%level] | [${HOSTNAME}] | [%thread] | [%logger{36}] | --> %msg|%n "/>

拦截器配置

/**
 * 描述:拦截器配置
 *
 * @author zuozewei
 * @create 2018-12-30 12:54
 **/
@Configuration
public class MyWebMvcConfigurer extends WebMvcConfigurerAdapter {

    @Override
    public void addInterceptors(InterceptorRegistry registry) {

        /**
         * 多个拦截器组成一个拦截器链
         * addPathPatterns 用于添加拦截规则
         * excludePathPatterns 用于排除拦截
         */
        registry.addInterceptor(new ControllerInterceptor()).addPathPatterns("/**");
        super.addInterceptors(registry);
    }
}

自定义日志注解

/**
 * 日志注解类
 * @author zuozewei
 *
 */
@Target({ElementType.TYPE, ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface Log {
    /**
     * 日志描述，这里使用了@AliasFor 别名。spring提供的
     * @return
     */
    @AliasFor("desc")
    String value() default "";

    /**
     * 日志描述
     * @return
     */
    @AliasFor("value")
    String desc() default "";

    /**
     * 是否忽略
     * @return
     */
    boolean ignore() default false;
}

TIPS：熟悉Spring常用注解类的通信，对 @AliasFor 应该不陌生。它是Spring 提供的一个注解，主要是给注解的属性起名别的。让使用注解时，更加的容易理解（比如给 value 属性起别名）。一般上是配对别名。由于是 Spring 框架提供的，所以要使其生效，可以使用 AnnotationUtils.synthesizeAnnotation或者 AnnotationUtils.getAnnotation方法调用获取注解

日志切面

/**
 * 日志切面类
 * Created by zuozewei on 2018/12/12.
 */
@Aspect  //申明一个切面
@Component
public class LogAspect {

    private static final Logger log = LoggerFactory.getLogger(LogAspect.class);
    private static final String dateFormat = "yyyy-MM-dd HH:mm:ss";
    private static final String STRING_START = "\n>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>\n";
    private static final String STRING_END   = "\n<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n";

    //设置切入点
    @Pointcut("within(@org.springframework.web.bind.annotation.RestController *)")
    public void serviceLog() {
    }

    /**
     * 切换方法，记录日志
     * @param joinPoint
     * @return
     * @throws Throwable
     */
   @Around("serviceLog()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
        Method method = signature.getMethod();
        Class<?> targetClass = method.getDeclaringClass();

        StringBuffer classAndMethod = new StringBuffer();

        Log classAnnotation = targetClass.getAnnotation(Log.class);
        Log methodAnnotation = method.getAnnotation(Log.class);

        if (classAnnotation != null) {
            if (classAnnotation.ignore()) {
                return joinPoint.proceed();
            }
            classAndMethod.append(classAnnotation.value()).append("-");
        }

        if (methodAnnotation != null) {
            if (methodAnnotation.ignore()) {
                return joinPoint.proceed();
            }
            classAndMethod.append(methodAnnotation.value());
        }

        String target = targetClass.getName() + "#" + method.getName();

        String params = null;
             params = JSONObject.toJSONStringWithDateFormat(joinPoint.getArgs(), dateFormat, SerializerFeature.WriteMapNullValue);

        log.info(STRING_START + "{} 开始调用--> {} 参数:{}", classAndMethod.toString(), target, params);

        long start = System.currentTimeMillis();
        Object result = joinPoint.proceed();
        long timeConsuming = System.currentTimeMillis() - start;

        log.info("\n{} 调用结束<-- {} 返回值:{} 耗时:{}ms" + STRING_END, classAndMethod.toString(), target, JSONObject.toJSONStringWithDateFormat(result, dateFormat, SerializerFeature.WriteMapNullValue), timeConsuming);
        return result;
    }
}

配置启动

启动类加入注解 @EnableAspectJAutoProxy，生效注解。另一说法，默认引入pom依赖就是默认开启的。无所谓，加了就是了，加上总之是个好习惯。

@SpringBootApplication
@EnableAspectJAutoProxy
@Slf4j
public class LogbackdemoApplication {

    public static void main(String[] args) {
        SpringApplication.run(LogbackdemoApplication.class, args);
        log.info("程序启动！");
    }
}

控制层

/**
 * aop统一异常示例
 * @author oKong
 *
 */
@RestController
public class DemoController {
    /**
     * 简单方法示例
     * @param hello
     * @return
     */
    @RequestMapping("/aop")
    @Log(value="请求了aopDemo方法")
    public String aopDemo(String hello) {
        return "请求参数为：" + hello;
    }

    /**
     * 不拦截日志示例
     * @param hello
     * @return
     */
    @RequestMapping("/notaop")
    @Log(ignore=true)
    public String notAopDemo(String hello) {
        return "此方法不记录日志，请求参数为：" + hello;
    }
}

测试 logback

测试统一拦截日志

浏览器访问：http://127.0.0.1:8888/aop/?content=”我是测试内容”

日志前面的 8B7B6968FB9A45BD8A3681AF3B123212 就是通过logback 的 MDC 做到的

>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
请求了aopDemo方法 开始调用--> com.zuozewei.logbackdemo.controller.DemoController#aopDemo 参数:["”我是测试内容”"]|
- | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.913] | [INFO] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.l.controller.DemoController] | --> 请求参数：content:”我是测试内容”|
- | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.913] | [WARN] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.l.controller.DemoController] | --> 请求参数：content:”我是测试内容”|
- | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.913] | [ERROR] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.l.controller.DemoController] | --> 请求参数：content:”我是测试内容”|
- | [8B7B6968FB9A45BD8A3681AF3B123212] | [20181230 12:12:28.914] | [INFO] | [appletekimbp] | [http-nio-8888-exec-1] | [c.z.logbackdemo.aspect.LogAspect] | --> 
请求了aopDemo方法 调用结束<-- com.zuozewei.logbackdemo.controller.DemoController#aopDemo 返回值:"2018-12-30T12:12:28.913,content:”我是测试内容”" 耗时:56ms
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

从上图可以看到，日志输出内容元素具体如下：

requestUUID：一次请求是唯一的
时间日期：精确到毫秒
日志级别：ERROR, WARN, INFO, DEBUG or TRACE
主机名：
进程ID：
类路径：
分隔符： --> 标识实际日志的开始
日志内容：

日志切面的响应：

请求了aopDemo方法 开始调用--> com.zuozewei.logbackdemo.controller.DemoController#aopDemo 参数:["”我是测试内容”"]|
com.zuozewei.logbackdemo.controller.DemoController#aopDemo 返回值:"2018-12-30T12:12:28.913,content:”我是测试内容”" 耗时:56ms

测试忽略拦截日志

浏览器访问：http://127.0.0.1:8888/notaop/?content=”我是测试内容”

- | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.749] | [INFO] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.aspect.ControllerInterceptor] | --> ControllerInterceptor preHandle 在请求处理之前生成 logback requestUUID:E5FB9C1D66514C2783B8E4C8024562F4|
- | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.753] | [INFO] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.controller.DemoController] | --> 请求参数：content:”不记录日志“|
- | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.753] | [WARN] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.controller.DemoController] | --> 请求参数：content:”不记录日志“|
- | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.754] | [ERROR] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.controller.DemoController] | --> 请求参数：content:”不记录日志“|
- | [E5FB9C1D66514C2783B8E4C8024562F4] | [20181230 12:13:57.794] | [INFO] | [appletekimbp] | [http-nio-8888-exec-5] | [c.z.l.aspect.ControllerInterceptor] | --> ControllerInterceptor postHandle 请求处理之后清除 logback MDC requestUUID|

从上面看到日志切面被忽略。