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

前言

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

在測試環境中，前端調用咱們服務一個接口時發現巨慢無比，響應時間超過了30s，簡直沒法忍受！！java

查看日誌顯示是咱們服務在經過Feign請求調用另外一個服務的GET接口時一直超時，而後重試了一直直到失敗。可是奇怪的是手動經過ip+端口請求這個超時的GET接口時卻響應速度很快。apache

這就很奇怪了，以前一直調用好好的接口，怎麼如今就一直超時呢？此時的我是滿腦子問號。。。tomcat

現象

前端調用咱們服務(這裏叫作服務A)的一個查詢接口，這裏前端用的是POST請求，咱們服務又會經過Feign調用到另外一個服務(這裏叫作服務B)的一個接口，這個接口對外提供GET形式的調用。markdown

從現象上來看就是調用咱們服務特別慢，一個請求響應幾十秒，具體流程以下：架構

問題排查

當時腦子中出現的疑惑就是太奇怪了，以前一隻調用的接口不該該會出現這種狀況，並且手動經過ip+端口去調用的話響應速度很快的，因而找了服務B對外開發的同窗一塊兒看，由於本身忽略了一些重要的日誌信息，因此這裏走了很多彎路，在同事的幫助下本身也將這個問題梳理清楚了。app

問題的根本緣由是咱們在GET請求的Header中傳遞了Content-Length參數，並且服務B近期添加了一個jar包，jar中有一個攔截器作了一些事情致使了這個問題。我這裏從源碼層面上梳理下整個問題的根本緣由，以及之後如何避免此類問題！socket

對於這個問題，本身本地分別啓動服務A和服務B，以DEBUG模式啓動，發現能夠穩定重現，並且能夠看到在調用服務B卡住時候的堆棧信息：工具

服務A發起的請求卡住的緣由是在awaitLatch()被掛起了，到了這裏纔算是找到了問題緣由的突破口，下面繼續往上一步步跟蹤就能夠找到問題的所在了，下面會一步步認真分析。oop

問題緣由

這裏問題的緣由實際上是經過上面問題排查反推出來的：

前端調用服務端接口時，由於是post請求，因此header中傳遞的有Content-Length屬性，調用feign請求時，不論get仍是post請求，公司底層包中有個Feign攔截器會將前端請求Header屬性賦值給feign請求中的Header，致使咱們發送的GET請求Header中也含有Content-Length屬性。

ps: 這一點很坑，依賴的底層包加了一個Feign攔截器，咱們是經過打印feign請求日誌在控制檯纔看到Content-Length屬性的，最後跟蹤到這個FeignInterceptor中的

服務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就會走這個邏輯鏈路呢？別急，繼續往下看，後面還有更精彩的分析......

解決方案

服務B取消有問題jar包的依賴
修改問題jar包中Filter的配置，判斷只有Post請求才去讀取body屬性
接口調用方添加配置若是是GET請求時過濾掉Content-Length屬性(主要緣由)
修改底層依賴包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的概念，默許你們都知道這個，若是不太清楚的還能夠參考： blog.piaoruiqing.com/2019/09/08/…

一個簡單的Content-Length確實難住了我，請求的不規範纔是此次問題的真正緣由。而排查出來這個問題也花費了不少時間，不過這些都是挺值得的，一我的的成長離不開各類問題的洗禮，但願你們閱讀完也會有所收穫。