利用 AOP 打印方法入参、返回值、描述、耗时

介绍

公司项目有需求想要打印方法的入参和返回值, 还要求打印方法的说明。

之前都是在方法的第一行手动打印 log, return 之前再打印返回值, 有多个返回点时需要出现重复代码, 有太多非业务代码显得凌乱。

后来采用 AOP 配置自定义 @Log 注解实现了此功能(主要是用于设置方法说明), 包括方法耗时统计。方法的入参和返回值都采用 fastjson 序列化。现贴出来, 一来给自己做个记录, 二来分享供大家参考指正。

依赖

<dependency>
    <groupId>com.alibaba</groupId>
    <artifactId>fastjson</artifactId>
</dependency>
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjweaver</artifactId>
</dependency>
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-context</artifactId>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
</dependency>

注解

package com.ecej.esmart.core.annotation;

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * Created by junbaor on 2017/5/12.
 */
@Target({ElementType.TYPE, ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface Log {

    /**
     * log 说明
     *
     * @return
     */
    String value() default "";

    /**
     * 是否忽略,比如类上面加的有注解,类中某一个方法不想打印可以设置该属性为 true
     *
     * @return
     */
    boolean ignore() default false;
}

实现

package com.ecej.esmart.core.common;

import com.alibaba.fastjson.JSONObject;
import com.alibaba.fastjson.serializer.SerializerFeature;
import com.ecej.esmart.core.annotation.Log;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;

import java.lang.reflect.Method;

/**
 * Created by junbaor on 2017/5/12.
 */
@Aspect
@Order(100)
@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("execution(* com.ecej.esmart..service.impl..*(..)) || execution(* com.ecej.esmart.http.controller..*(..))")
    public void serviceLog() {
    }

    @Around("serviceLog()")
    public Object around(ProceedingJoinPoint joinPoint) {
        try {
            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 = 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;
        } catch (Throwable throwable) {
            log.error(throwable.getMessage(), throwable);
        }
        return null;
    }

}

测试

TestService.java

package com.ecej.esmart.gateway.service.impl;

import com.ecej.esmart.core.annotation.Log;
import com.ecej.esmart.gateway.dto.input.commonpo.Apply;
import org.springframework.stereotype.Service;

@Service
@Log("测试服务")
public class TestService {

    @Log("回声方法")
    public Apply echo(Apply apply) throws InterruptedException {
        Thread.sleep(500);
        return apply;
    }
}

JunitTestService.java

@Autowired
private TestService testService;


@Test
public void init() throws InterruptedException {
    Apply apply = new Apply();
    apply.setEmpId(101);
    apply.setOrderId(9512548);
    apply.setPhone("18011217376");
    apply.setAppointmentTime(new Date());
    System.out.println(testService.echo(apply));
}

日志效果：

[20171116 11:00:32.692] | [INFO] | [DESKTOP-MDJIPJH] | [main] | [com.ecej.esmart.core.common.LogAspect] | [--> 
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
测试服务-回声方法 开始调用--> com.ecej.esmart.gateway.service.impl.TestService#echo 参数:[{"appointmentTime":"2017-11-16 11:00:32","empId":101,"orderId":9512548,"phone":"18011217376","platform":"EMP"}]
[20171116 11:00:33.214] | [INFO] | [DESKTOP-MDJIPJH] | [main] | [com.ecej.esmart.core.common.LogAspect] | [--> 
测试服务-回声方法 调用结束<-- com.ecej.esmart.gateway.service.impl.TestService#echo 返回值:{"appointmentTime":"2017-11-16 11:00:32","empId":101,"orderId":9512548,"phone":"18011217376","platform":"EMP"} 耗时:521ms
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<