写点什么

【原创】经验分享:一个 Content-Length 引发的血案 (almost....)

发布于: 2020 年 09 月 08 日

前言


上周在工作中遇到一个问题,挺有意思,这里记录一下。上周在工作中遇到一个问题,挺有意思,这里记录一下。标题起的很唬人,这个问题差点引发血案,花哥还是很严谨的一个人,后面备注了almost....


在测试环境中,前端调用我们服务一个接口时发现巨慢无比,响应时间超过了 30s,简直无法忍受!!


查看日志显示是我们服务在通过Feign请求调用另一个服务的GET接口时一直超时,然后重试了一直直到失败。 但是奇怪的是手动通过ip+端口请求这个超时的GET接口时却响应速度很快。


这就很奇怪了,之前一直调用好好的接口,怎么现在就一直超时呢?此时的我是满脑子问号。。。


现象

前端调用我们服务(这里叫做服务A)的一个查询接口,这里前端用的是POST请求,我们服务又会通过Feign调用到另一个服务(这里叫做服务B)的一个接口,这个接口对外提供GET形式的调用。


从现象上来看就是调用我们服务特别慢,一个请求响应几十秒,具体流程如下:



问题排查


当时脑子中出现的疑惑就是太奇怪了,之前一只调用的接口不应该会出现这种情况,而且手动通过ip+端口去调用的话响应速度很快的,于是找了服务B对外开发的同学一起看,因为自己忽略了一些重要的日志信息,所以这里走了不少弯路,在同事的帮助下自己也将这个问题梳理清楚了。


问题的根本原因是我们在GET请求的Header中传递了Content-Length参数,而且服务 B 近期添加了一个jar包,jar中有一个拦截器做了一些事情导致了这个问题。我这里从源码层面上梳理下整个问题的根本原因,以及以后如何避免此类问题!


对于这个问题,自己本地分别启动服务A服务B,以DEBUG模式启动,发现可以稳定重现,而且可以看到在调用服务B卡住时候的堆栈信息


服务A发起的请求卡住的原因是在awaitLatch()被挂起了,到了这里才算是找到了问题原因的突破口,下面继续往上一步步跟踪就可以找到问题的所在了,下面会一步步认真分析。


问题原因


这里问题的原因其实是通过上面问题排查反推出来的:


  1. 前端调用服务端接口时,因为是post请求,所以header中传递的有Content-Length属性,调用feign请求时,不论get还是post请求,公司底层包中有个Feign拦截器会将前端请求Header属性赋值给feign请求中的Header,导致我们发送的GET请求Header中也含有Content-Length属性。


ps: 这一点很坑,依赖的底层包加了一个 Feign 拦截器,我们是通过打印 feign 请求日志在控制台才看到 Content-Length 属性的,最后跟踪到这个 FeignInterceptor 中的


  1. 服务 B 刚好依赖了另一个jar包,该包中包含一个Filter拦截器,它会读取发送的请求body数据,然后做一些日志打印。而且这个jar包依赖也是他们刚加的,他们使用该包中的其他一些工具类


public class ChannelFilter implements Filter {    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {        if (servletRequest instanceof HttpServletRequest) {            requestWrapper = new RequestWrapper((HttpServletRequest)servletRequest);            log.info("Http RequestURL : {}, Method : {}, RequestParam : {}, RequestBody : {}", new Object[]{((HttpServletRequest)servletRequest).getRequestURL(), ((HttpServletRequest)servletRequest).getMethod(), JSON.toJSON(servletRequest.getParameterMap()), ((RequestWrapper)requestWrapper).getBody()});        }

filterChain.doFilter((ServletRequest)requestWrapper, servletResponse); }

public void destroy() { }}
public class RequestWrapper extends HttpServletRequestWrapper { private static final Logger log = LoggerFactory.getLogger(RequestWrapper.class); private final String body;
public RequestWrapper(HttpServletRequest request) { super(request); StringBuilder stringBuilder = new StringBuilder(); BufferedReader bufferedReader = null; ServletInputStream inputStream = null;
try { inputStream = request.getInputStream(); if (inputStream != null) { bufferedReader = new BufferedReader(new InputStreamReader(inputStream)); char[] charBuffer = new char[4096]; boolean var6 = true;
int bytesRead; while((bytesRead = bufferedReader.read(charBuffer)) != -1) { stringBuilder.append(charBuffer, 0, bytesRead); } } } catch (IOException var19) { log.error(var19.getMessage(), var19); } }}
复制代码


在执行request body读取的代码时使用到:


while((bytesRead = bufferedReader.read(charBuffer)) != -1) {   stringBuilder.append(charBuffer, 0, bytesRead);}
复制代码


bufferedReader.read()最终会调用到Tomcatorg.apache.tomcat.util.net.NioBlockingSelector.read()的方法读取request中的body属性:


int keycount = 1; while(!timedout) {    if (keycount > 0) { //only read if we were registered for a read        read = socket.read(buf);        if (read != 0) {            break;        }    }    try {        if ( att.getReadLatch()==null || att.getReadLatch().getCount()==0) att.startReadLatch(1);        poller.add(att,SelectionKey.OP_READ, reference);        if (readTimeout < 0) {            att.awaitReadLatch(Long.MAX_VALUE, TimeUnit.MILLISECONDS);        } else {            att.awaitReadLatch(readTimeout, TimeUnit.MILLISECONDS);        }    } catch (InterruptedException ignore) {        // Ignore    }}
复制代码


这里因为GET请求的body为空,所以socket.read() 返回为 0,进而走到att.awaitReadLatch(readTimeout, TimeUnit.MILLISECONDS);


protected void awaitLatch(CountDownLatch latch, long timeout, TimeUnit unit) throws InterruptedException {    if ( latch == null ) throw new IllegalStateException("Latch cannot be null");    latch.await(timeout,unit);}
复制代码


这里就会调用到LockSuport.parkNanos(time) 接口 直到超时,此时的你们会不会仍然有疑惑,为什么Header中传递了Content-Length就会走这个逻辑链路呢?别急,继续往下看,后面还有更精彩的分析......


解决方案


  1. 服务B取消有问题jar包的依赖

  2. 修改问题jar包中Filter的配置,判断只有Post请求才去读取body属性

  3. 接口调用方添加配置如果是GET请求时过滤掉Content-Length属性(主要原因)

  4. 修改底层依赖包FeignInterceptor,判断请求的方式然后再针对Header赋值(公司底层依赖的包我们不太好修改)


其实最应该修改的是方案 4,只是这个是全公司都会依赖的一个底层包,如果改动起来需要通知架构组等等,而且影响面会比较大。


最终我们先采用方案 3,在我们请求链路中去做一些判断,去除GET请求中Content-Length的传递。

解决原理


接下来就是真正原理的地方了,当服务端发出feign请求后,一定会走Tomcat中的org.apache.coyote.http11.Http11Processor.prepareRequest()方法,代码如图:


如果contentLength >= 0,那么会添加一个org.apache.coyote.http11.filters.IdentityInputFilter类,在服务B添加的jar包中的RequestWrapper中的bufferedReader.read()会调用到 org.apache.coyote.http11.filters.IdentityInputFilter.doRead() 方法:


这个方法又会直接调用到 org.apache.tomcat.util.net.NioBlockingSelector.read()中:



因为GET请求的request body为空,所以这里通过socket去读取时返回为 0,直接运行下面的awaitReadLatch() 方法,这里会调用LockSuport.parkNanos(time) 接口 直到超时,这也是为什么我们每次feign请求都会超时的原因。


但是如果服务请求方配置了传递的Content-Length为空呢?这里会构造一个org.apache.coyote.http11.filters.VoidInputFilter,这个拦截器的构造在上面Http11Processor.prepareRequest()图示中已经标明:



显而易见,这里直接返回-1,不会再去调用NioBlockingSelector.read() 方法了,所以成功解决此问题,这也是问题的关键所在。


总结


这里没有过多的去介绍Content-Length的概念,默许大家都知道这个,如果不太清楚的还可以参考:

https://blog.piaoruiqing.com/2019/09/08/do-you-know-content-length/


一个简单的Content-Length确实难住了我,请求的不规范才是这次问题的真正原因。而排查出来这个问题也花费了很多时间,不过这些都是挺值得的,一个人的成长离不开各种问题的洗礼,希望大家阅读完也会有所收获。


欢迎关注:


发布于: 2020 年 09 月 08 日阅读数: 537
用户头像

专注Java生态,励志做最接地气的技术分享者 2018.05.05 加入

公众号:一枝花算不算浪漫 欢迎关注~

评论 (2 条评论)

发布
用户头像
貌似http标准没有规定get不可以有body. 关键是content-length的值必须和body的数据的字节长度匹配,如果是匹配的,比如0,此时卡死是接收方的问题,否则是发送方的问题。
2020 年 09 月 08 日 16:43
回复
是的,这篇文章主要是问题排查的一个过程,问题本质是很简单的,get请求没有body体 也不需要去解析。
2020 年 09 月 15 日 17:51
回复
没有更多了
【原创】经验分享:一个Content-Length引发的血案(almost....)