最近排查一個(gè)bug，發(fā)現(xiàn)了一系列有意思的東西，對(duì)「自定義線程池」、「Jetty線程模型」都有了一些新的認(rèn)識(shí)。

本文預(yù)計(jì)閱讀時(shí)間10分鐘，包括：

• 問題表現(xiàn)
• 常見原因篩查
• 根因與源碼分析
• 最佳實(shí)踐
• 一些小TIPS

1、問題表現(xiàn)

預(yù)發(fā)環(huán)境偶發(fā)請(qǐng)求失敗異常，服務(wù)端顯示錯(cuò)誤信息為：

Required String parameter 'seriesbaid' is not present 

對(duì)應(yīng)controller的api為

乍一看，是一個(gè)非常簡單的異常，請(qǐng)求參數(shù)里面沒有帶seriesbaid，導(dǎo)致失敗。

但是，經(jīng)過確認(rèn)，前端請(qǐng)求參數(shù)已經(jīng)攜帶了seriesbaid，而且為“偶發(fā)失敗”，并不是常見的參數(shù)傳遞問題。

2、常見原因篩查

2.1 網(wǎng)關(guān)參數(shù)丟失?

由于前端請(qǐng)求到達(dá)后端服務(wù)中會(huì)經(jīng)過網(wǎng)關(guān)，所以一開始懷疑是否網(wǎng)關(guān)丟失了傳遞參數(shù)。

經(jīng)過 調(diào)用鏈分析，在偶發(fā)的失敗的請(qǐng)求中，也確認(rèn)已經(jīng)傳遞了querystring。所以網(wǎng)關(guān)沒有丟失參數(shù)傳遞。

2.2 特殊字符導(dǎo)致參數(shù)轉(zhuǎn)換失敗 ?

既然已經(jīng)傳遞了querystring到后端服務(wù)，那么一種常見的原因，由于queryString中帶有特殊字符而導(dǎo)致解析成queryParam失敗了。

會(huì)是這個(gè)問題嗎?

我們通過在服務(wù)中繼承一個(gè)spring-web的OncePerRequestFilter，對(duì)請(qǐng)求參數(shù)進(jìn)行打印。

在偶發(fā)的失敗的請(qǐng)求中，找到了以下日志

2021-12-29 15:36:05,536 INFO [com.xxx.interceptor.RequestLoggingFilter] - shouldLog - swanparameter:traceId:fb2266d3687911ecb5f3cf045ea19ac3; query:seriesbaid=3FO4K4SLX2IW&x_plugin=custom&x_bz=&locale=zh_CN&x_resourceId=&x_resourceVersion=; parameterMap:{}; 

比較遺憾，我們確認(rèn)了請(qǐng)求中確實(shí)有querystring而沒有成功解析為queryParam，但是這個(gè)querystring中，并沒有期望的特殊字符，講道理是可以解析成功的。

既然常見原因無法解釋，只能去源碼撈一把了。

2.3 去源碼撈一把

我們的網(wǎng)絡(luò)容器使用了jetty，所以HttpServletRequest的實(shí)現(xiàn)是jetty的Request類。

Request類中，對(duì)queryString的解析是在 getParameters() 的時(shí)候。

我們發(fā)現(xiàn)，當(dāng)異常請(qǐng)求進(jìn)來的時(shí)候，這里的判斷

_queryParameter竟然不是null，而是一個(gè)空對(duì)象。

而正常請(qǐng)求，這里判斷_queryParameter為null，然后進(jìn)行解析。

所以，還是要從源碼去分析了。

3、根因與源碼分析

3.1 _queryParamter為什么不是null了?

我們通過在Request類中設(shè)置多個(gè)斷點(diǎn)，找到了原因。整理過程如下圖所示。

1)同步請(qǐng)求A快速完成返回。

當(dāng)請(qǐng)求A進(jìn)來，在一次Http請(qǐng)求結(jié)束后(controller方法返回客戶端)，會(huì)進(jìn)行相應(yīng)的recycle()操作，這里包括Requst對(duì)象執(zhí)行recycle()方法，清理相關(guān)參數(shù)，包括_queryParameters。

2)異步任務(wù)延遲響應(yīng)，在recycle()后重新設(shè)置了_queryParameter屬性。

在請(qǐng)求A執(zhí)行過程中，使用「自定義線程池」異步執(zhí)行了一個(gè)方法B(方法較慢)。方法B中，從RequestContextHolder中獲取了HttpServletRequest，然后通過request.getParameter()獲取請(qǐng)求頭。

因?yàn)榇藭r(shí)_queryParameters為null，因此extractQueryParameters()方法就解析了一個(gè)空的對(duì)象放進(jìn)去。

3)新請(qǐng)求C進(jìn)入，返回異常。

當(dāng)新的請(qǐng)求C進(jìn)入后端服務(wù)，拿到了同一個(gè)Request對(duì)象，由于此時(shí)_queryParameters不為null，因此跳過了extractQueryParameters()，導(dǎo)致應(yīng)該解析的queryString無法被解析，controller拋出異常。

總結(jié)：一旦主線程執(zhí)行完畢，完成recycle過程，而異步線程執(zhí)行較慢，異步線程中的任何request.getParameter()行為會(huì)破壞Request對(duì)象的recycle，導(dǎo)致_queryParameters屬性為空對(duì)象而不是null，從而導(dǎo)致新的請(qǐng)求失敗。

3.2 異步線程中，RequestContextHolder還能拿到Request對(duì)象?(根本原因)

我們知道RequestContextHolder是基于ThreadLocal實(shí)現(xiàn)的。因此，在異步線程中，是無法直接通過

RequestContextHolder.getRequestAttributes()獲取主線程的HttpServletRequest。

問題出在了「自定義線程池」

ThreadPoolExecutorWithMonitor中。

里面自定義實(shí)現(xiàn)了一個(gè)內(nèi)部類DecorateRunnableTask來處理任務(wù)。

內(nèi)部類DecorateRunnableTask繼承了內(nèi)部類DecorateTask，保存了主線程的RequestAttributes對(duì)象。

然后在異步線程執(zhí)行前，通過before()方法設(shè)置到了當(dāng)前線程的RequestContextHolder中。

總結(jié)：給異步線程傳遞RequestAttributes對(duì)象，是造成Request對(duì)象泄漏的根本原因!

3.3 兩個(gè)請(qǐng)求，為什么會(huì)共享一個(gè)Request對(duì)象?

本來上面的分析基本已經(jīng)找到了Bug的原因，但是我仔細(xì)想了下，又覺得有點(diǎn)奇怪。

兩個(gè)請(qǐng)求，為什么會(huì)共享一個(gè)Request對(duì)象?

如果是使用了相關(guān)池化技術(shù)，那怎么能在兩個(gè)請(qǐng)求找到同一個(gè)對(duì)象，然后穩(wěn)定復(fù)現(xiàn)呢?因此，又繼續(xù)去研究了下jetty的相關(guān)內(nèi)容。

jetty 9.x整體架構(gòu)圖：

SelectorManager + ManagedSelector +QueuedThreadPool 組成了「Reactor線程模型」。對(duì)于一個(gè)http請(qǐng)求，SelectorManager分配給某一個(gè)ManagedSelector創(chuàng)建HttpConnection對(duì)象，然后在QueuedThreadPool中執(zhí)行相應(yīng)的IO操作。

HttpConnection對(duì)象持有HttpChannel對(duì)象，HttpChannel中持有了Request對(duì)象(就是HttpServletRequest)。

網(wǎng)關(guān)到后端服務(wù)之間使用的是Http請(qǐng)求，默認(rèn)為長連接，因此，在短時(shí)間內(nèi)的新的請(qǐng)求(長連接結(jié)束前)，會(huì)復(fù)用同一個(gè)HttpConnection對(duì)象。

4、最佳實(shí)踐

不要給異步線程傳遞RequestAttributes對(duì)象并進(jìn)行保存。

如果需要相關(guān)請(qǐng)求參數(shù)，可以新建上下文對(duì)象存儲(chǔ)參數(shù)后進(jìn)行傳遞?；蛘呤褂肨ransmittableThreadLocal。

5、一些小TIPS

5.1 jetty源碼不匹配

在對(duì)jetty的Request類進(jìn)行debug時(shí)，一開始這里遇到一個(gè)小坑，idea一直源碼匹配不上。從github上把 jetty源碼拉下來，按照引入的jetty版本進(jìn)行本地mvn install，還是不一致。

根據(jù)pom的依賴分析，可以看到引入的jetty版本為9.4.12。

后來突然想起來，這個(gè)項(xiàng)目雖然是springboot項(xiàng)目，但是并不是打成jar包通過內(nèi)置jetty容器啟動(dòng)的。而是打成了war包，本地通過jetty-maven-plugin的jetty:run啟動(dòng)的。這里使用的jetty版本為9.4.9。

所以，我們需要按照jetty-maven-plugin的版本來選擇jetty的源碼。

5.2 「偶發(fā)問題」難以復(fù)現(xiàn)

考慮到篇幅原因與閱讀體驗(yàn)，本文在排查過程中，沒有展開說明一個(gè)非常困難的地方————本地如何穩(wěn)定復(fù)現(xiàn)「偶發(fā)問題」異常請(qǐng)求。

真實(shí)排查過程中，本地穩(wěn)定復(fù)現(xiàn)耗費(fèi)了大量時(shí)間。如果不是本地可以穩(wěn)定復(fù)現(xiàn)，后面的debug也無從談起。

后面主要根據(jù)代碼的近期變更情況，發(fā)現(xiàn)了一個(gè)異步請(qǐng)求的引入，將異步改為同步后，發(fā)現(xiàn)就不會(huì)再出現(xiàn)這個(gè)問題了。

所以才從異步請(qǐng)求出發(fā)，多次嘗試后，進(jìn)行了穩(wěn)定復(fù)現(xiàn)。

所以本次排查的一個(gè)重要收獲，就是對(duì)于一些故障的排查，可以考慮從近期的「各種變更」中去尋找線索。