API 接口定义 添加 @ApiOperation 注解触发中间件 bug 问题分析
背景
我有一个服务 A ，写了一个接口定义如下：
@RequestMapping({"/config/coupon"})
public interface CouponOperateTaskService {
@PostMapping({"/list"})
@ApiOperation("优惠券操作任务列表")
BizPageResponse<CouponOperateListResponse> couponOperateList(@RequestBody @Validated CouponOperateRequest request);
}
打了一个 api 的jar 包发布到 maven 仓库，被 服务 B 引用：
@FeignClient(name = "ext-service-mkt-coupon-config", configuration = FeignSupportConfig.class)
public interface CouponOperateTaskClient extends CouponOperateTaskService {
}
B 服务进行调用：
@Resource
private CouponOperateTaskClient operateTaskClient;
@ApiOperation("优惠券操作任务列表")
public BizPageResponse<CouponOperateListResponse> couponOperateTaskList(@RequestBody @Validated CouponOperateRequest request) {
return operateTaskClient.couponOperateList(request);
}
调用之后response就会返回异常信息：
{
"code": 10025,
"message": "系统异常,错误码:null",
"data": {
"results": [],
"total": 0,
"pageCount": 0,
"currentIndex": 0,
"hasNext": false
}
}
更诡异的是并且控制台和日志系统都搜不到错误日志。
分析
上面为背景，经过分析后，有两个问题需要解决：
- 为什么会报错？
- 为什么没有日志？
我们先看第二个问题，为什么没有错误日志。
据我所知，我们的项目中间件同一封装了全局的日常处理类，那为啥没有生效呢？找到封装好的 异常处理类：com.tuhu.springcloud.common.advice.ExceptionHandlerAdvice
@ConditionalOnClass(BizResponse.class)
@RestControllerAdvice
@Slf4j
public class ExceptionHandlerAdvice {
/**
* 参数异常处理
*
* @param validException validException
* @return BizBaseResponse
*/
@ExceptionHandler(value = { MethodArgumentNotValidException.class, BindException.class })
@ResponseStatus(value = HttpStatus.OK)
@ResponseBody
@SuppressWarnings({ "rawtypes" })
public BizResponse handleMethodArgumentNotValidException(Exception validException) {
log.info("SC服务请求参数有误:{}", validException.getMessage(), validException);
BindingResult bindingResult = null;
if (validException instanceof MethodArgumentNotValidException) {
bindingResult = ((MethodArgumentNotValidException) validException).getBindingResult();
} else if (validException instanceof BindException) {
bindingResult = ((BindException) validException).getBindingResult();
}
if (null == bindingResult || null == bindingResult.getFieldError()) {
return new BizResponse<>(BizErrorCodeEnum.PARAM_ERROR);
}
return new BizResponse<>(BizErrorCodeEnum.PARAM_ERROR, bindingResult.getFieldError().getDefaultMessage());
}
}
发现 @ConditionalOnClass(BizResponse.class) 只针对 BizResponse.class 的响应封装有效，踩坑+1 ！！！
那我们先改为 BizResponse 的响应试试呢？
@Resource
private CouponOperateTaskClient operateTaskClient;
@ApiOperation("优惠券操作任务列表")
public BizResponse<CouponOperateListResponse> couponOperateTaskList(@RequestBody @Validated CouponOperateRequest request) {
BizPageResponse<CouponOperateListResponse> couponOperateListResponseBizPageResponse = operateTaskClient.couponOperateList(request);
return BizResponse.success();
}
这次我们把 Response 改为 BizResponse 封装的，那 com.tuhu.springcloud.common.advice.ExceptionHandlerAdvice这个异常拦截应该能够拦截到了吧，试试看：
{
"code": 10025,
"message": "系统异常,错误码:null",
"data": null
}
结果，试试就逝世！😥，踩坑+100 ！！！
首先说明的是，operateTaskClient.couponOperateList(request) 这个请求服务肯定是能够通的，用 postman 测试没问题，只有在 代码里面调用会出现这个异常。
为了找到日志原因，我手动 try catch 住下面代码：
发现代码并未走到 catch 块中。把代码 operateTaskClient.couponOperateList(request) 去掉返回就正常，加上这行代码就会异常，并且这行代码 还 catch 不到任何异常。
此刻我仿佛遇见了鬼打墙。
冷静下来，仔细分析一波，可以断定，指定有什么中间件写的拦截器做了什么骚操作。
根据 Response 响应，有个关键字：错误码 ，感觉很熟悉的样子，这让我想到之前踩过的另一个坑：[关于 @RestControllerAdvice 不生效的问题]https://wiki.tuhu.cn/pages/viewpage.action?pageId=219085320
在这片文章中，我分析了 线上错误日志为啥找不到的原因，最终定位到 ：是运维把
com.tuhu.springcloud.common.annotation.AbstractControllerLogAspect这个类的日志做了 50% 的丢弃。
又是 com.tuhu.springcloud.common.annotation.AbstractControllerLogAspect 这个类。
至此我已经高度怀疑是这个日志的切面类搞的鬼了。
所以，进去找到这个类打个断点一步步试试：
发现是这个记录日志的切面类中出现了空指针异常
进一步定位出现 NPE 的代码
就是这行代码了：
Long timeTaken = System.currentTimeMillis() - threadLocal.get();
即 threadLocal.get() 得到的是一个 null ，导致空指针异常。
再进一步分析为何 threadLocal.get() 返回的是个 null。
先来看 这个切面类，的作用：主要是拦截 com.tuhu 包下的所有标注了 @ApiOperation 注解的方法：
@Pointcut("execution(* com.tuhu..*.*(..))")
public void controllerLog() {
}
@Around(value = "controllerLog()&& @annotation(logAnnotation)")
public Object doAround(ProceedingJoinPoint joinPoint, ApiOperation logAnnotation) throws Throwable {
// 执行目标方法之前
Object result;
try {
// 方法执行前
this.doBefore(joinPoint, logAnnotation);
// 执行目标方法
result = joinPoint.proceed();
// 执行目标方法之后
doAfterReturning(joinPoint, result, logAnnotation);
} catch (Throwable ex) {
return this.doAfterThrowingAdvice(joinPoint, logAnnotation, ex);
} finally {
// 执行完毕,返回
this.doAfter(joinPoint, logAnnotation);
}
return result;
}
其中产生 NPE 的方法是这个 doAfterReturning(joinPoint, result, logAnnotation);
看这个方法实现：
public void doAfterReturning(JoinPoint joinPoint, Object result, ApiOperation logAnnotation) throws Throwable {
Long timeTaken = System.currentTimeMillis() - threadLocal.get();
MDC.put("timetaken", timeTaken.toString());
threadLocal.remove();
if (controllerLogEnabled) {
log.info("SC服务结束调用:{},耗时={}ms,result={}", logAnnotation.value(), timeTaken,
controllerLogResponseEnabled ? result : "");
}
}
这个方法主要打印接口耗时和响应结果。但是在计算耗时的时候，从 threadLocal 中取得了开始时间，并且在 后面进行了remove 操作 threadLocal.remove();。
试想，如果一个请求中，这个拦截方法进来了两次，那第二次不就是 threadLocal.get() 返回 null 了吗。
个人觉得，这里的写法有一些问题，不应该从 threadLocal 获取请求开始时间，可以使用环绕通知的切面，自行 try catch。
那为什么会进来两次呢，因为通过 FeignClient 调用的下游接口，在接口定义上面也打了一个 @ApiOperation 注解
导致 这个方法拦截器进来了两次，第二次触发 NPE。
而在触发异常之后，又自己 catch 住：
在 doAfterThrowingAdvice 方法捕获了异常，进行异常处理
打断点可以看到 log 走到了红框处，但是我的 控制台并没有打印出日志。
然后走到了 最后的 doResponse 方法，返回一个响应对象：
protected Object doResponse(JoinPoint joinPoint, BizEnum errorCode, String errorMessage) {
Class returnType = ((MethodSignature) (joinPoint.getSignature())).getReturnType();
if (BizResponse.class.equals(returnType)) {
return new BizResponse<>(errorCode, errorMessage);
}
if (BizPageResponse.class.equals(returnType)) {
return new BizPageResponse<>(errorCode, errorMessage);
}
return new BizExtResponse<>(errorCode, errorMessage);
}
总结
至此，两个问题都分析完毕。
间接原因是B 服务依赖的下游接口 api 定义 多加了 @ApiOperation 注解，
直接原因就是，中间的这个 日志拦截类没有考虑到这种情况，产生了 NPE。
最后还有一个问题未解决,
那就是本地启动时， 这个日志切面类命名拦截到了异常，也走到了打印日志的地方，但是为何控制台就没有打印出日志呢？
详细代码可参考： com.tuhu.springcloud.common.annotation.AbstractControllerLogAspect 169行：