一、背景
项目中经常会看到在所有的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
都打出来了
异常日志