统一配置服务日志自定义打印

1. 背景

近期服务器的磁盘总是报内存不够，排查了一下发现日志暴涨，业务量增加是无可避免的，翻了一下日志，发现很多接口把入参和出参都打印了，比如分页数据结果十分庞大，属于无效日志，不应该打印。为了自由地控制接口入参和出参的打印，做了一个决定：入参必须打，出参可自定义打印。

自定义打印可使用方法上的注解来解决，如@LogAnnotation，

@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
@Documented
public @interface LogAnnotation {

    /**
     * 是否打印接口出参
     */
    boolean logResult() default true;
}

若方法上加上了

@LogAnnotation(logResult()=false)

就不打印接口返回结果，思路有以下两种：

• 使用AOP+注解来自定义配置日志打印
• 使用dubbo filter+注解来自定义配置日志打印

第一种可使用ProceedingJoinPoint来获取目标方法，第二种方法困难在于如何从invoker中获取目标方法。

2. 使用AOP+注解来自定义配置日志打印

@Component
@Aspect
public class GlobalExceptionAspect {

    private static final Logger log = LoggerFactory.getLogger(GlobalExceptionAspect.class);

    //对ao层得异常进行全局拦截
    @Around("execution(com.yt.asd.common.domain.RpcResult com.yt.cmc.biz.ao..*.*(..))")
    public RpcResult doProcess(ProceedingJoinPoint point) {
        String targetClass = point.getTarget().getClass().getSimpleName();
        MethodSignature signature = (MethodSignature) point.getSignature();
        String methodName = signature.getMethod().getName();
        RpcResult result = RpcResult.newInstance();
        try {

            log.info("[{}-{}] 请求参数：param:{}, 请求时间:{}", targetClass, methodName, Arrays.asList(point.getArgs()), DateUtil.dateToString(new Date()));
          
            Stopwatch stopwatch = Stopwatch.createStarted();
            // 方法执行
            result = (RpcResult) point.proceed();
          
            stopwatch.stop();
          
            // 若取执行方法
            Method method = point.getTarget().getClass().getMethod(methodName, signature.getMethod().getParameterTypes());
          
            if(logResponse(method)) {
                // 打印返回值
                log.info("[{}-{}] success, 返回结果:{}, 消耗:{}, 时间:{}", targetClass, methodName, JSON.toJSONString(result), stopwatch.toString(), DateUtil.dateToString(new Date()));
            } else {
                // 不打印返回值
                log.info("[{}-{}] success, 消耗:{}, 时间:{}", targetClass, methodName, stopwatch.toString(), DateUtil.dateToString(new Date()));
            }
            return result;
          
        } catch (Exception e) {
          //异常处理......
        }
    }

    private boolean logResponse(Method method) {
        LogAnnotation annotation = method.getAnnotation(LogAnnotation.class);
        if (annotation == null) {
            annotation = method.getDeclaringClass().getAnnotation(LogAnnotation.class);
        }
        if(annotation == null) {
            return true;
        }
        return annotation.logResult();
    }

}

上面在若取执行方法处，即

Method method = point.getTarget().getClass().getMethod(methodName, signature.getMethod().getParameterTypes());

由于dubbo对外方法都是采用动态代理的方式(默认Javassist动态代理)，若直接使用以下方法来获取Method的话，只会获取到方法的签名信息，如：

public abstract com.yt.asd.common.domain.RpcResult com.yt.cmc.shop.api.BActExtendApi.getActInfo(com.yt.cmc.shop.domain.query.BactGetQuery)

而且从上面签名信息中获取不到方法上标注的注解信息。

Method method = point.getSignature()).getMethod();

除了上面的方式，也可采用以下方式来获取真正执行的Method。

Method method = ClassUtils.getMostSpecificMethod(signature.getMethod(), point.getTarget().getClass());

// method打印出
public com.yt.asd.common.domain.RpcResult com.yt.cmc.biz.ao.shop.BActExtendApiImpl.getActInfo(com.yt.cmc.shop.domain.query.BactGetQuery)

这样可通过 LogAnnotation 注解的 logResult 属性值来决定是否打印返回结果日志。

3. 使用dubbo filter+注解来自定义配置日志打印

这里使用的dubbo默认javassist动态代理

@Component
@Slf4j
public class LogFilter implements Filter {

    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        String className = invoker.getInterface().getName();
        String methodName = invocation.getMethodName();
        String arguments = JSON.toJSONString(invocation.getArguments());

        try {
            log.info("[{}-{}] 请求参数：param:{}, 请求时间:{}", className, methodName, arguments, DateUtil.getFormantDate(new Date(), DateUtil.MILLS_FORMANT));
            Stopwatch stopwatch = Stopwatch.createStarted();

            Result invoke = invoker.invoke(invocation);

            stopwatch.stop();

            String value = JSON.toJSONString(invoke.getValue());


            Method signatureMethod = invoker.getInterface().getMethod(methodName, invocation.getParameterTypes());
            Class targetClass = getTargetClass(invoker).getClass();
            Method method = ClassUtils.getMostSpecificMethod(signatureMethod, targetClass);

            log.info("signatureMethod:{},targetClass:{}, method:{}", signatureMethod, targetClass, method);

            if(logResponse(method)) {
                // 打印返回值
                log.info("[{}-{}] success, 返回结果:{}, 消耗:{}, 时间:{}", className, methodName, value, stopwatch.toString(), DateUtil.getFormantDate(new Date(), DateUtil.MILLS_FORMANT));
            } else {
                // 不打印返回值
                log.info("[{}-{}] success, 消耗:{}, 时间:{}", className, methodName, stopwatch.toString(), DateUtil.getFormantDate(new Date(), DateUtil.MILLS_FORMANT));
            }
            return invoke;
        } catch (Exception e) {
        }

        return null;
    }


    private boolean logResponse(Method method) {
        LogAnnotation annotation = method.getAnnotation(LogAnnotation.class);
        if (annotation == null) {
            annotation = method.getDeclaringClass().getAnnotation(LogAnnotation.class);
        }
        if(annotation == null) {
            return true;
        }
        return annotation.logResult();
    }

    /**
    ** 获取invoker的目标方法
    **/
    private Object getTargetClass(Object invoker) throws Exception {

        Field invokerField = invoker.getClass().getDeclaredField("invoker");
        invokerField.setAccessible(true);
        AbstractProxyInvoker javassistProxyFactoryInvoker = (AbstractProxyInvoker)invokerField.get(invoker);

        Field proxy = javassistProxyFactoryInvoker.getClass().getSuperclass().getDeclaredField("proxy");
        proxy.setAccessible(true);
        Object proxyValue = proxy.get(javassistProxyFactoryInvoker);

        Field jdkDynamicAopProxy = proxyValue.getClass().getSuperclass().getDeclaredField("h");
        jdkDynamicAopProxy.setAccessible(true);
        Object jdkDynamicAopProxyValue = jdkDynamicAopProxy.get(proxyValue);

        Field advised = jdkDynamicAopProxyValue.getClass().getDeclaredField("advised");
        advised.setAccessible(true);
        return ((AdvisedSupport) advised.get(jdkDynamicAopProxyValue)).getTargetSource().getTarget();
    }

}

Dubbo Filter的配置信息就不再简介。