记一次远程API调用失败

记一次远程API调用失败

最近开发忙，项目紧，系统出现一些忽隐忽现的问题，本地也不能复现，当时也无法理解，就先搁置了，现在回想起来，这里还是明智的。

这个bug很神奇

• 今天，原本好好的API，突然抽风爆出数据转换异常，看看异常信息，指向一个远程调用API response json转换异常

• 2020-04-09 15:12:57.236 DEBUG 22236 --- [http-nio-9010-exec-2] c.l.framework.remote.crm.CrmRemoteApi    : [CrmRemoteApi#getProviderType] ---> POST http://micro-service-crm/remote/provider/type/list HTTP/1.1
  2020-04-09 15:13:02.336 DEBUG 22236 --- [http-nio-9010-exec-5] c.l.framework.remote.crm.CrmRemoteApi    : [CrmRemoteApi#getProviderType] <--- HTTP/1.1 200 (5133ms)
  2020-04-09 15:13:02.339 ERROR 22236 --- [http-nio-9010-exec-5] c.l.f.exception.GlobleExceptionHandler   : Exception:Error while extracting response for type [java.util.List<com.lansen.framework.dto.provider.CrmMaterialInfoPartnerEntity>] and content type [application/json;charset=utf-8]; nested exception is org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: Cannot deserialize instance of `java.util.ArrayList` out of START_OBJECT token; nested exception is com.fasterxml.jackson.databind.exc.MismatchedInputException: Cannot deserialize instance of `java.util.ArrayList` out of START_OBJECT token
   at [Source: (PushbackInputStream); line: 1, column: 1]
  
  feign.codec.DecodeException: Error while extracting response for type [java.util.List<com.lansen.framework.dto.provider.CrmMaterialInfoPartnerEntity>] and content type [application/json;charset=utf-8]; nested exception is org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: Cannot deserialize instance of `java.util.ArrayList` out of START_OBJECT token; nested exception is com.fasterxml.jackson.databind.exc.MismatchedInputException: Cannot deserialize instance of `java.util.ArrayList` out of START_OBJECT token
   at [Source: (PushbackInputStream); line: 1, column: 1]
      at feign.SynchronousMethodHandler.decode(SynchronousMethodHandler.java:180)
      at feign.SynchronousMethodHandler.executeAndDecode(SynchronousMethodHandler.java:140)
      at feign.SynchronousMethodHandler.invoke(SynchronousMethodHandler.java:78)
      at feign.ReflectiveFeign$FeignInvocationHandler.invoke(ReflectiveFeign.java:103)
      at com.sun.proxy.$Proxy213.getProviderType(Unknown Source)
  

• 这个问题应该不难，看了一下异常远程API

•     @Override
      public List<Map<String, String>> getProviderType(List<String> materialNos) {
          return crmMaterialInfoPartnerService.getProviderType(materialNos);
      }
  

• 看代码返回值不符合开发规范**（开发规范返回值不能使用Map，必须是具体实体类）**，找了一下负责这个模块功能的开发者“乐宝”（乐宝是我们项目组的一位呆萌男孩，是个态度和工作都很努力的大眼小伙儿，遇到问题总是眼睛瞳孔放大，眼神一片迷茫还伴随着不断点头，总之非常可爱），简单讲解了一下异常信息，把这个问题交给“乐宝”解决。下午的时候找到乐宝，问了一下修复情况，乐宝还是一头雾水，看我过来了，试探问是不是我这个返回实体有包含自己的情况

• public class CrmMaterialInfoPartnerEntity extends BaseEntity {
      @TableField(exist = false)
      List<CrmMaterialInfoPartnerEntity> materialList;
  }
  

• 想到这点，他赶紧删掉测了一圈，问题还是一样，由于时间紧，这块儿自引用先按下不表，叮嘱乐宝先尝试解决，不行就换一种写法试试，经过了几轮儿排查，不知不觉已经是下午6点了，乐宝说改好了，代码提交开始发测试版本，版本发完测试验证问题依然存在，乐宝本地验证没问题，不过他发现第一次是正常的，清理了redis，问题就出现了，这问题奇怪了，怎么会跟redis有关系呢，顿时陷入了沉思中…

这个bug很调皮

• 乐宝说返回List集合的接口都有问题，他已经修复了2个模块了，测试后仍然报错，找不到问题的原因，先让乐宝保留本地修改的代码，暂不提交。我开始盯着代码思考这个问题，一般这种转换异常的问题，要么是返回值映射有问题，要么是传参映射有问题，顺着这两个思路我打开了debug模式，A服务远程调用B服务，先检查B服务有没有接收到请求，排查B服务收到了请求，但是B服务还未响应请求，A服务突然报错了what？？？…

• 沉思中时，老大哥也过来帮忙排查，我俩简单同步问题信息后，定位到gateway的feign调用超时问题，开始修改配置，把超时时间设置大些，把redis超时时间也调大，正在尝试测试时，另一个项目组也模拟出一种偶现问题，调用远程API时提示强制退出登录，这是什么情况？猜测两个问题应该来源一个出处，为什么远程API会跟redis有关系呢？于是过去看了一下强制退出登录的问题，也没摸到头绪，回来时老大哥模拟出来一种新思路，服务刚启动时清空redis问题会出现，这时候把远程服务重启，再次清理redis发现问题没有了，重新整理思路，代码开始在脑子里浮现，每一个服务都有一个权限认证拦截器，只有这里使用到了redis，难道是这里出现的问题？废话不多说，开始在这里debug，一番排查后，发现远程服务验证token时候出错了，根据报错信息还是很难分辨出为什么异常，老大哥提出我们在这里打一下token看一下调用时候token有什么问题，

• 2020-04-09 18:53:33.913 DEBUG 15880 --- [http-nio-9002-exec-2] c.l.f.web.filter.BaseInterceptor         : 当前访问URL:/remote/provider/type/list,
  redis  token: eyJhbGciOiJIUzI1NiJ9.eyJqdGkiOiJkMWMyNzExNC1mZmU2LTQ0MTktODMzNC1hNjQwNjQ5YTYwODQiLCJpc3MiOiJKV1QiLCJzdWIiOiJ7XCJ1c2VySWRcIjpcImQ3YzNlNmY0NGMwMmUxMmM2NTVjOGRmM2NhZDM3MDFkXCIsXCJ1c2VyTmFtZVwiOlwiYW5kZXJzXCIsXCJ0eXBlXCI6XCJhY2NvdW50XCIsXCJhcHBsaWNhdGlvbklkXCI6XCJiMmFlZmNhMmI4YjA0YzJiYTEyZGYwY2JlZTkwdDJjZVwiLFwidGltZVwiOjE1ODY0Mjk1NjgzMzB9IiwiaWF0IjoxNTg2NDI5NTY4LCJleHAiOjE1ODcwMzQzNjh9.uvWNCUZR9JucS5aBdKdNui8bPxXVlXW_-wD1-pbt4rI 
  remote token: eyJhbGciOiJIUzI1NiJ9.eyJqdGkiOiJjMjQ0MmZjYy1mM2QxLTRjMzEtOTc5Yi00NDlhNTg4ZTRmMjMiLCJpc3MiOiJKV1QiLCJzdWIiOiJ7XCJ1c2VySWRcIjpcImQ3YzNlNmY0NGMwMmUxMmM2NTVjOGRmM2NhZDM3MDFkXCIsXCJ1c2VyTmFtZVwiOlwiYW5kZXJzXCIsXCJ0eXBlXCI6XCJhY2NvdW50XCIsXCJhcHBsaWNhdGlvbklkXCI6XCJiMmFlZmNhMmI4YjA0YzJiYTEyZGYwY2JlZTkwdDJjZVwiLFwidGltZVwiOjE1ODY0MzA1NTI2MTh9IiwiaWF0IjoxNTg2NDMwNTUyLCJleHAiOjE1ODcwMzUzNTJ9.SdqEVuVfUn7oPOoYZmVTwugONbfg8Vy12W2ffpNqdnM
  

两次token不一致，why？？？

• 只有远程API调用的时候token不一致，检查了一遍认证拦截器，没有发现异常问题，突然想到了远程API的feign拦截器，打开代码一看，恍然大悟，就是这里了

•     @Override
      public void apply(RequestTemplate requestTemplate) {
          FeignRequestContext feignRequestContext = FeignRequestContextLocal.getInstance().get();
          if (Objects.nonNull(feignRequestContext)) {
              requestTemplate.headers(feignRequestContext.buildHeaders());
          }else if(Objects.nonNull(CommonUtils.getRequest())) {
              requestTemplate.headers(getHeads(CommonUtils.getRequest()));
          }
      }
      private Map<String, Collection<String>> getHeads(HttpServletRequest request) {
          FeignRequestContext feignRequestContext = new FeignRequestContext(request);
          FeignRequestContextLocal.getInstance().set(feignRequestContext);
          return feignRequestContext.buildHeaders();
      }
  

• 由于有异步处理的业务场景，这里使用了线程变量存储远程上下文参数，这里没有考虑到清理，去掉这里的线程变量，程序运行舒畅了，到此问题圆满解决了，真是一场深刻的bug排查。