前言

上周在工作中遇到一个问题,挺有意思,这里纪录一下。上周在工作中遇到一个问题,挺有意思,这里纪录一下。题目起的很唬人,这个问题差点引发血案,花哥照样很严谨的一个人,后面备注了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()最终会挪用到Tomcat 中org.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包的依赖

    ,

    联博统计

    www.tianyulinmo.com采用以太坊区块链高度哈希值作为统计数据,联博以太坊统计数据开源、公平、无任何作弊可能性。联博统计免费提供API接口,支持多语言接入。

    ,
  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确实难住了我,请求的不规范才是这次问题的真正缘故原由。而排查出来这个问题也花费了许多时间,不外这些都是挺值得的,一个人的发展离不开种种问题的洗礼,希望人人阅读完也会有所收获。

迎接关注: