【原創】經驗分享：一個Content-Length引發的血案(almost....)
阿新 • • 發佈：2020-09-08
## 前言
上週在工作中遇到一個問題，挺有意思，這裡記錄一下。上週在工作中遇到一個問題，挺有意思，這裡記錄一下。標題起的很唬人，這個問題差點引發血案，**花哥**還是很嚴謹的一個人，後面備註了`almost....`
在測試環境中，前端呼叫我們服務一個介面時發現巨慢無比，響應時間超過了**30s**，簡直無法忍受！！
檢視日誌顯示是我們服務在通過`Feign`請求呼叫另一個服務的`GET`介面時一直超時，然後重試了一直直到失敗。 但是奇怪的是手動通過`ip+埠`請求這個超時的`GET`介面時卻響應速度很快。
這就很奇怪了，之前一直呼叫好好的介面，怎麼現在就一直超時呢？**此時的我是滿腦子問號。。。**
## 現象
前端呼叫我們服務(這裡叫做`服務A`)的一個查詢介面，這裡前端用的是`POST`請求，我們服務又會通過`Feign`呼叫到另一個服務(這裡叫做`服務B`)的一個介面，這個介面對外提供`GET`形式的呼叫。
從現象上來看就是呼叫我們服務特別慢，一個請求響應幾十秒，具體流程如下：
## 問題排查
當時腦子中出現的疑惑就是太奇怪了，之前一隻呼叫的介面不應該會出現這種情況，而且手動通過`ip+埠`去呼叫的話響應速度很快的，於是找了`服務B`對外開發的同學一起看，因為自己忽略了一些重要的日誌資訊，所以這裡走了不少彎路，在同事的幫助下自己也將這個問題梳理清楚了。
問題的根本原因是我們在`GET`請求的`Header`中傳遞了`Content-Length`引數，而且服務B近期添加了一個`jar`包，`jar`中有一個攔截器做了一些事情導致了這個問題。我這裡從**原始碼層面**上梳理下整個問題的根本原因，以及以後如何避免此類問題！
對於這個問題，自己本地分別啟動`服務A`和`服務B`，以`DEBUG`模式啟動，發現可以穩定重現，而且可以看到在呼叫`服務B`卡住時候的**堆疊資訊**：
`服務A`發起的請求卡住的原因是在`awaitLatch()`被掛起了，到了這裡才算是找到了問題原因的突破口，下面繼續往上一步步跟蹤就可以找到問題的所在了，下面會一步步認真分析。
## 問題原因
這裡問題的原因其實是通過上面問題排查反推出來的：
1. 前端呼叫服務端介面時，因為是`post`請求，所以`header`中傳遞的有`Content-Length`屬性，呼叫`feign`請求時，不論`get`還是`post`請求，公司底層包中有個`Feign`攔截器會將前端請求`Header`屬性賦值給`feign`請求中的`Header`，導致我們傳送的`GET`請求`Header`中也含有`Content-Length`屬性。
> ps: 這一點很坑，依賴的底層包加了一個Feign攔截器，我們是通過列印feign請求日誌在控制檯才看到Content-Length屬性的，最後跟蹤到這個FeignInterceptor中的
2. 服務B剛好依賴了另一個`jar`包，該包中包含一個`Filter`攔截器，它會讀取傳送的請求`body`資料，然後做一些日誌列印。而且這個`jar`包依賴也是他們剛加的，他們使用該包中的其他一些工具類
```java
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`讀取的程式碼時使用到：
```java
while((bytesRead = bufferedReader.read(charBuffer)) != -1) {
stringBuilder.append(charBuffer, 0, bytesRead);
}
```
`bufferedReader.read()`最終會呼叫到`Tomcat` 中`org.apache.tomcat.util.net.NioBlockingSelector.read()`的方法讀取`request`中的`body`屬性：
```java
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)`;
```java
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()`方法，程式碼如圖：
如果`contentLength >