切面实现Dubbo请求日志以及全局异常处理

一、背景

项目中经常会看到在所有的Rpc接口实现中记录请求参数，以及try catch，每个方法都来一次，看着就不舒服，类似下面这段代码

public CloudServerResponse<Boolean> updateExpressInfo(SendAppraisalExpressParam sendAppraisalExpressParam) {

        log.info("updateExpressInfo:{}",JSON.toJSONString(sendAppraisalExpressParam));
        CloudServerResponse<Boolean> cloudServerResponse = new CloudServerResponse<>();
        try{
            int i = this.updateExpress(sendAppraisalExpressParam);
            return cloudServerResponse.setResult(i>=1);
        }catch (Exception e){
            log.error("AppraisalLogisticService.updateExpressInfo:{}",e);
            return cloudServerResponse;
        }

    }

二、实现

2.1 需要日志记录的东西

• 请求的服务签名
• 请求入参
• 请求结果
• 请求时间
• 如果发生了异常，则把异常的返回结果封装一下，记录异常信息

2.2 精简后的代码

    public CloudServerResponse<Boolean> updateExpressInfo(SendAppraisalExpressParam sendAppraisalExpressParam) {
        CloudServerResponse<Boolean> cloudServerResponse = new CloudServerResponse<>();
        int i = this.updateExpress(sendAppraisalExpressParam);
        return cloudServerResponse.setResult(i>=1);
    }

是不是清爽多了：）

2.3 实现代码

@Aspect
@Slf4j
@Configuration
@ConditionalOnProperty(name = "wwdz.rpc.service.log.enabled")
public class DubboServiceAspect {
    /**
     * 返回值类型为Response的Service
     */
    @Pointcut("@within(org.apache.dubbo.config.annotation.Service) && execution(public com.wwdz.mall.common.vo.response.CloudServerResponse com.wwdz..*.*(..))")
    private void servicePointcut() {
    }

    /**
     * 任何持有@Transactional注解的方法
     */
    @Pointcut(value = "@annotation(org.springframework.transaction.annotation.Transactional)")
    private void transactionalPointcut() {
    }

    /**
     * 异常处理切面
     * 将异常包装为Response，避免dubbo进行包装
     *
     * @param pjp 处理点
     * @return Object
     */
    @Around("servicePointcut() && !transactionalPointcut()")
    public Object doAround(ProceedingJoinPoint pjp) {
        Object[] args = pjp.getArgs();
        Long currentTimeMillis = System.currentTimeMillis();
        try {
            Object result = pjp.proceed();
            processSuccessfulLog(pjp, args, result, currentTimeMillis);
            return result;
        } catch (BizException e) { // 业务自定义异常
            CloudServerResponse cloudServerResponse = e.createResponse();
            processSuccessfulLog(pjp, args, cloudServerResponse, currentTimeMillis);
            return cloudServerResponse;
        }
        catch (Throwable e) {
            processException(pjp, args, e, currentTimeMillis);
            return CloudResultCode.INTERAL_ERROR.createResponse();
        }
    }

    /**
     * 记录请求成功日志
     * @param joinPoint
     * @param args
     * @param result
     * @param startCurrentTimeMillis
     */
    private void processSuccessfulLog(ProceedingJoinPoint joinPoint, Object[] args, Object result, Long startCurrentTimeMillis) {
        MethodSignature methodSign = (MethodSignature)joinPoint.getSignature();
        UnLog unLog = methodSign.getMethod().getAnnotation(UnLog.class);
        StringBuilder logMsg = new StringBuilder();
        logMsg.append(logServiceMsg(joinPoint));
        logMsg.append(logArgs(args));
        logMsg.append(logResponse(result));
        logMsg.append(logTimeMillis(startCurrentTimeMillis));
        if(unLog == null){
            log.info(logMsg.toString());
        }
    }

    /**
     * 任何持有@Transactional注解的方法异常处理切面
     * 将自定义的业务异常转为RuntimeException:
     * 1.规避dubbo的包装，让customer可以正常获取message
     * 2.抛出RuntimeException使事务可以正确回滚
     * 其他异常不处理
     *
     * @param pjp 处理点
     * @return Object
     */
    @Around("servicePointcut() && transactionalPointcut()")
    public Object doTransactionalAround(ProceedingJoinPoint pjp) throws Throwable {
        try {
            return pjp.proceed();
        } catch (Throwable e) {
            // dubbo会将异常捕获进行打印，这里就不打印了
            // processException(pjp, args, e);
            throw new RuntimeException(e.getMessage());
        }
    }

    /**
     * 处理异常
     *  @param joinPoint 切点
     * @param args      参数
     * @param throwable 异常
     * @param startCurrentTimeMillis
     */
    private void processException(final ProceedingJoinPoint joinPoint, final Object[] args, Throwable throwable, Long startCurrentTimeMillis) {
        StringBuilder logMsg = new StringBuilder();
        logMsg.append(logServiceMsg(joinPoint));
        logMsg.append(logArgs(args));
        logMsg.append(logTimeMillis(startCurrentTimeMillis));
        log.error(logMsg.toString(), throwable);
    }

    /**
     * 拼接入参
     * @param args
     * @return
     */
    private String logArgs(Object[] args){
        if(args == null || args.length <= 0){
            return "Request: No request param\n";
        }
        List<Object> usableArgs = new ArrayList<>();
        Collections.addAll(usableArgs, args);
        return "Request: " + JSONObject.toJSONString(usableArgs) + "\n";
    }

    /**
     * 拼接出参
     * @param retVal
     * @return
     */
    private String logResponse(Object retVal) {
        return "Response: " + JSONObject.toJSONString(retVal) + "\n";
    }

    /**
     * 拼接服务接口信息
     * @param joinPoint
     * @return
     */
    private String logServiceMsg(final ProceedingJoinPoint joinPoint){
        return "Service: " + joinPoint.toLongString() + "\n";
    }

    /**
     * 拼接执行时间
     * @param startCurrentTimeMillis
     * @return
     */
    private String logTimeMillis(long startCurrentTimeMillis){
        return "TimeMillis: " + (System.currentTimeMillis() - startCurrentTimeMillis) + "\n";
    }
}

以上代码注解应该挺清楚，代码也比较简单，使用的时候注意要在配置中添加一下，默认是不开启的

wwdz.rpc.service.log.enabled = true

还有一点要注意，假如有一些请求入参或者请求结果很大，日志文件可能会暴涨，这种情况下如果确定这个日志没有太大的价值，可以在方法上加@Unlog注解，屏蔽这个方法的日志

/**
 * 注解加上后不打请求日志
 */
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface UnLog {
}

执行一下，看看日志打印的结果：

服务名service
入参request
结果response
耗时TimeMillis
都打出来了

异常日志