记一次API 接口定义 添加 @ApiOperation 注解触发中间件 bug 问题分析

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
   }
}

更诡异的是并且控制台和日志系统都搜不到错误日志。

分析

上面为背景，经过分析后，有两个问题需要解决：

1. 为什么会报错？
2. 为什么没有日志？

我们先看第二个问题，为什么没有错误日志。

据我所知，我们的项目中间件同一封装了全局的日常处理类，那为啥没有生效呢？找到封装好的 异常处理类：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行：