【原創(chuàng)】經(jīng)驗分享：一個Content-Length引發(fā)的血案(almost....)

前言

上周在工作中遇到一個問題，挺有意思，這里記錄一下。上周在工作中遇到一個問題，挺有意思，這里記錄一下。標(biāo)題起的很唬人，這個問題差點引發(fā)血案，花哥還是很嚴(yán)謹(jǐn)?shù)囊粋€人，后面?zhèn)渥⒘?code>almost....

在測試環(huán)境中，前端調(diào)用我們服務(wù)一個接口時發(fā)現(xiàn)巨慢無比，響應(yīng)時間超過了30s，簡直無法忍受！！

查看日志顯示是我們服務(wù)在通過Feign請求調(diào)用另一個服務(wù)的GET接口時一直超時，然后重試了一直直到失敗。 但是奇怪的是手動通過ip+端口請求這個超時的GET接口時卻響應(yīng)速度很快。

這就很奇怪了，之前一直調(diào)用好好的接口，怎么現(xiàn)在就一直超時呢？此時的我是滿腦子問號。。。

現(xiàn)象

前端調(diào)用我們服務(wù)(這里叫做服務(wù)A)的一個查詢接口，這里前端用的是POST請求，我們服務(wù)又會通過Feign調(diào)用到另一個服務(wù)(這里叫做服務(wù)B)的一個接口，這個接口對外提供GET形式的調(diào)用。

從現(xiàn)象上來看就是調(diào)用我們服務(wù)特別慢，一個請求響應(yīng)幾十秒，具體流程如下：

問題排查

當(dāng)時腦子中出現(xiàn)的疑惑就是太奇怪了，之前一只調(diào)用的接口不應(yīng)該會出現(xiàn)這種情況，而且手動通過ip+端口去調(diào)用的話響應(yīng)速度很快的，于是找了服務(wù)B對外開發(fā)的同學(xué)一起看，因為自己忽略了一些重要的日志信息，所以這里走了不少彎路，在同事的幫助下自己也將這個問題梳理清楚了。

問題的根本原因是我們在GET請求的Header中傳遞了Content-Length參數(shù)，而且服務(wù)B近期添加了一個jar包，jar中有一個攔截器做了一些事情導(dǎo)致了這個問題。我這里從源碼層面上梳理下整個問題的根本原因，以及以后如何避免此類問題！

對于這個問題，自己本地分別啟動服務(wù)A和服務(wù)B，以DEBUG模式啟動，發(fā)現(xiàn)可以穩(wěn)定重現(xiàn)，而且可以看到在調(diào)用服務(wù)B卡住時候的堆棧信息：

服務(wù)A發(fā)起的請求卡住的原因是在awaitLatch()被掛起了，到了這里才算是找到了問題原因的突破口，下面繼續(xù)往上一步步跟蹤就可以找到問題的所在了，下面會一步步認(rèn)真分析。

問題原因

這里問題的原因其實是通過上面問題排查反推出來的：

1. 前端調(diào)用服務(wù)端接口時，因為是post請求，所以header中傳遞的有Content-Length屬性，調(diào)用feign請求時，不論get還是post請求，公司底層包中有個Feign攔截器會將前端請求Header屬性賦值給feign請求中的Header，導(dǎo)致我們發(fā)送的GET請求Header中也含有Content-Length屬性。

ps: 這一點很坑，依賴的底層包加了一個Feign攔截器，我們是通過打印feign請求日志在控制臺才看到Content-Length屬性的，最后跟蹤到這個FeignInterceptor中的

2. 服務(wù)B剛好依賴了另一個jar包，該包中包含一個Filter攔截器，它會讀取發(fā)送的請求body數(shù)據(jù)，然后做一些日志打印。而且這個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);
        }
    }
}

在執(zhí)行request body讀取的代碼時使用到：

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

bufferedReader.read()最終會調(diào)用到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，進(jìn)而走到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);
}

這里就會調(diào)用到LockSuport.parkNanos(time) 接口 直到超時，此時的你們會不會仍然有疑惑，為什么Header中傳遞了Content-Length就會走這個邏輯鏈路呢？別急，繼續(xù)往下看，后面還有更精彩的分析......

解決方案

1. 服務(wù)B取消有問題jar包的依賴
2. 修改問題jar包中Filter的配置，判斷只有Post請求才去讀取body屬性
3. 接口調(diào)用方添加配置如果是GET請求時過濾掉Content-Length屬性(主要原因)
4. 修改底層依賴包FeignInterceptor，判斷請求的方式然后再針對Header賦值(公司底層依賴的包我們不太好修改)

其實最應(yīng)該修改的是方案4，只是這個是全公司都會依賴的一個底層包，如果改動起來需要通知架構(gòu)組等等，而且影響面會比較大。

最終我們先采用方案3，在我們請求鏈路中去做一些判斷，去除GET請求中Content-Length的傳遞。

解決原理

接下來就是真正原理的地方了，當(dāng)服務(wù)端發(fā)出feign請求后，一定會走Tomcat中的org.apache.coyote.http11.Http11Processor.prepareRequest()方法，代碼如圖：

如果contentLength >= 0，那么會添加一個org.apache.coyote.http11.filters.IdentityInputFilter類，在服務(wù)B添加的jar包中的RequestWrapper中的bufferedReader.read()會調(diào)用到 org.apache.coyote.http11.filters.IdentityInputFilter.doRead() 方法：

這個方法又會直接調(diào)用到 org.apache.tomcat.util.net.NioBlockingSelector.read()中：

因為GET請求的request body為空，所以這里通過socket去讀取時返回為0，直接運行下面的awaitReadLatch() 方法，這里會調(diào)用LockSuport.parkNanos(time) 接口 直到超時，這也是為什么我們每次feign請求都會超時的原因。

但是如果服務(wù)請求方配置了傳遞的Content-Length為空呢？這里會構(gòu)造一個org.apache.coyote.http11.filters.VoidInputFilter，這個攔截器的構(gòu)造在上面Http11Processor.prepareRequest()圖示中已經(jīng)標(biāo)明：

顯而易見，這里直接返回-1，不會再去調(diào)用NioBlockingSelector.read() 方法了，所以成功解決此問題，這也是問題的關(guān)鍵所在。

總結(jié)

這里沒有過多的去介紹Content-Length的概念，默許大家都知道這個，如果不太清楚的還可以參考：
https://blog.piaoruiqing.com/2019/09/08/do-you-know-content-length/

一個簡單的Content-Length確實難住了我，請求的不規(guī)范才是這次問題的真正原因。而排查出來這個問題也花費了很多時間，不過這些都是挺值得的，一個人的成長離不開各種問題的洗禮，希望大家閱讀完也會有所收獲。

歡迎關(guān)注：