經(jīng)驗分享：一個Content-Length引發(fā)的血案……
前言
上周在工作中遇到一個問題，挺有意思，這里記錄一下。標(biāo)題起的很唬人，這個問題差點引發(fā)血案，花哥還是很嚴(yán)謹(jǐn)?shù)囊粋€人，后面?zhèn)渥⒘?/span>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)真分析。
問題原因
這里問題的原因其實是通過上面問題排查反推出來的：
前端調(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中的
服務(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ù)往下看，后面還有更精彩的分析......
解決方案
服務(wù)B取消有問題jar包的依賴修改問題 jar包中Filter的配置，判斷只有Post請求才去讀取body屬性接口調(diào)用方添加配置如果是 GET請求時過濾掉Content-Length屬性(主要原因)修改底層依賴包 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ī)范才是這次問題的真正原因。如果這個問題直接上線，那肯定會引發(fā)一樁血案的，我也可能會被拖去"祭天"......
排查出來這個問題也花費了不少時間，不過這些都是挺值得的，一個人的成長離不開各種問題的洗禮，希望大家閱讀完也會有所收獲。
