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

引言

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

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

工程目录

总结

本文主要是简单介绍了利用 AOP 实现统一的请求日志记录功能。本示例未演示日志入库功能,后续再实现。在实际测试开发过程中,一般上都是将日志保存进行异步化后进行入库处理的,这点需要注意,日志记录不能影响正常的方法请求,若是同步的,会本末倒置的。

本文代码:

https://github.com/7DGroup/Java-API-Test-Examples

本文分享自微信公众号 - 7DGroup(Zee_7DGroup)

原文出处及转载信息见文内详细说明,如有侵权,请联系 yunjia_community@tencent.com 删除。

原始发表时间:2018-12-30

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

扫码关注云+社区

领取腾讯云代金券