【原創】經驗分享:一個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()最終會呼叫到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()方法,程式碼如圖:

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

相關文章