【原創】經驗分享：一個Content-Length引發的血案(almost....)

一枝花算不算浪漫發表於2020-09-08

前言

上週在工作中遇到一個問題，挺有意思，這裡記錄一下。上週在工作中遇到一個問題，挺有意思，這裡記錄一下。標題起的很唬人，這個問題差點引發血案，花哥還是很嚴謹的一個人，後面備註了almost....

在測試環境中，前端呼叫我們服務一個介面時發現巨慢無比，響應時間超過了30s，簡直無法忍受！！

檢視日誌顯示是我們服務在通過Feign請求呼叫另一個服務的GET介面時一直超時，然後重試了一直直到失敗。 但是奇怪的是手動通過ip+埠請求這個超時的GET介面時卻響應速度很快。

這就很奇怪了，之前一直呼叫好好的介面，怎麼現在就一直超時呢？此時的我是滿腦子問號。。。

現象

前端呼叫我們服務(這裡叫做服務A)的一個查詢介面，這裡前端用的是POST請求，我們服務又會通過Feign呼叫到另一個服務(這裡叫做服務B)的一個介面，這個介面對外提供GET形式的呼叫。

從現象上來看就是呼叫我們服務特別慢，一個請求響應幾十秒，具體流程如下：

請求流程.png

問題排查

當時腦子中出現的疑惑就是太奇怪了，之前一隻呼叫的介面不應該會出現這種情況，而且手動通過ip+埠去呼叫的話響應速度很快的，於是找了服務B對外開發的同學一起看，因為自己忽略了一些重要的日誌資訊，所以這裡走了不少彎路，在同事的幫助下自己也將這個問題梳理清楚了。

問題的根本原因是我們在GET請求的Header中傳遞了Content-Length引數，而且服務B近期新增了一個jar包，jar中有一個攔截器做了一些事情導致了這個問題。我這裡從原始碼層面上梳理下整個問題的根本原因，以及以後如何避免此類問題！

對於這個問題，自己本地分別啟動服務A和服務B，以DEBUG模式啟動，發現可以穩定重現，而且可以看到在呼叫服務B卡住時候的堆疊資訊：

執行緒堆疊資訊.png

服務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包的依賴
  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()方法，程式碼如圖：

Http11Processor.prepareRequest().png

如果contentLength >= 0，那麼會新增一個org.apache.coyote.http11.filters.IdentityInputFilter類，在服務B新增的jar包中的RequestWrapper中的bufferedReader.read()會呼叫到 org.apache.coyote.http11.filters.IdentityInputFilter.doRead() 方法：

wE7F6s.png

這個方法又會直接呼叫到 org.apache.tomcat.util.net.NioBlockingSelector.read()中：

NioBlockingSelector.read().png

因為GET請求的request body為空，所以這裡通過socket去讀取時返回為0，直接執行下面的awaitReadLatch() 方法，這裡會呼叫LockSuport.parkNanos(time) 介面 直到超時，這也是為什麼我們每次feign請求都會超時的原因。

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

VoidInputFilter.png

顯而易見，這裡直接返回-1，不會再去呼叫NioBlockingSelector.read() 方法了，所以成功解決此問題，這也是問題的關鍵所在。

總結

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

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

歡迎關注：
原創乾貨分享.png

相關文章