NoHttpResponseException: xxx failed to respond 問題分析

問題

HttpClient偶爾報(bào)NoHttpResponseException: xxx failed to respond

feign.RetryableException: xxx:80 failed to respond executing POST http://xx

復(fù)現(xiàn)方法

google得知,這個(gè)只會(huì)在服務(wù)器端keep-alive剛好過期的時(shí)間我們進(jìn)行訪問才能大概率復(fù)現(xiàn),方法如下:

wireshark進(jìn)行抓包得出底層服務(wù)器的keep-alive時(shí)間

寫一段程序,用于探測底層服務(wù)器的keep-alive:


image.png

開啟wireshark進(jìn)行抓包,執(zhí)行程序直到下圖出現(xiàn)即可停止

image.png

重點(diǎn)看左下角的紅色框,時(shí)間相差65秒左右,沒錯(cuò)從而可以得知底層服務(wù)器的keep-alive 是 65秒,也就是當(dāng)一個(gè)連接socket 65秒內(nèi)沒有數(shù)據(jù)交互,底層服務(wù)器就會(huì)認(rèn)為這個(gè)連接可以關(guān)閉了,因此才會(huì)在3分36秒進(jìn)行揮手操作發(fā)送一個(gè)FIN包,這時(shí)我們稍微改造一下這個(gè)程序,如下:


image.png

相比第一個(gè),有兩個(gè)改動(dòng)

加了一個(gè)循環(huán)
每次調(diào)用的間隔改成和底層服務(wù)器相同的65秒
我們清空wireshark,運(yùn)行該程序抓包,結(jié)果如下:


image.png

問題分析

image.png

紅色框1:前3個(gè)請(qǐng)求是建立連接的過程,三次握手,接著4個(gè)請(qǐng)求就是client和server的數(shù)據(jù)交互,著重看最后四個(gè)請(qǐng)求
9012 -> 59233 [FIN, ACK]:服務(wù)器主動(dòng)進(jìn)行關(guān)閉,給client發(fā)送了FIN包
59233 -> 9012 [ACK]:client進(jìn)行回應(yīng)ACK包
69233 -> 9012 [FIN, ACK]:按照四次揮手原則,client發(fā)現(xiàn)目前數(shù)據(jù)已經(jīng)發(fā)送完畢了,因此也發(fā)出FIN包
9012 -> 59233 [RST]:服務(wù)器直接返回一個(gè)RST
紅色框2:同2
紅色框3:前面的7個(gè)步驟都是相同的,建立連接,數(shù)據(jù)交互,區(qū)別唯獨(dú)在于綠色框
9012 -> 59233 POST /hy/json: client認(rèn)為服務(wù)器端可用,因此給服務(wù)器發(fā)送數(shù)據(jù)
9012 -> 59233 [FIN, ACK]:服務(wù)器認(rèn)為此連接已經(jīng)失效,因?yàn)槌^了65的keep-alive時(shí)間,主動(dòng)進(jìn)行關(guān)閉,給client發(fā)送了FIN包
59233 -> 9012 [ACK]:client進(jìn)行回應(yīng)ACK包
69233 -> 9012 [FIN, ACK]:按照四次揮手原則,client發(fā)現(xiàn)目前數(shù)據(jù)已經(jīng)發(fā)送完畢了,因此也發(fā)出FIN包
9012 -> 59233 [RST]:服務(wù)器直接返回一個(gè)RST 通過Seq=188,可判斷這條是給【9012 -> 59233 POST /hy/json】這個(gè)請(qǐng)求回的
9012 -> 59233 [RST]:服務(wù)器直接返回一個(gè)RST 通過Seq=189,可判斷這條是給【69233 -> 9012 [FIN, ACK]】回的
9012 -> 59233 [RST]:服務(wù)器直接返回一個(gè)RST 通過Seq=189,同6
通過分析抓包數(shù)據(jù),得出結(jié)果是,當(dāng)client客戶端認(rèn)為這條Socket連接有用,這時(shí)服務(wù)器端卻認(rèn)為該Socket連接無用,并主動(dòng)關(guān)閉,就會(huì)報(bào)錯(cuò),屬于臨界值沒有處理好的

這時(shí)有人就說了,為什么前兩次就沒有問題呢,原因是HttpClient會(huì)進(jìn)行連接過期是否可用的檢查,那么也就能理解這是httpclient的一個(gè)bug,即使httpclient有做這么一件事情,但是由于網(wǎng)絡(luò)I/O原因,導(dǎo)致httpclient認(rèn)為一個(gè)關(guān)閉了的連接是有效的,才報(bào)了這個(gè)錯(cuò)誤。

HttpClient為什么會(huì)復(fù)用一個(gè)已經(jīng)被關(guān)閉的連接

開啟debug日志


image.png

通過仔細(xì)分析HttpClient打印的debug日志,可發(fā)現(xiàn)左邊正常交互日志 打印了一串 "end of stream" 后進(jìn)行了連接的重新建立, connection established ,而右邊錯(cuò)誤日志打印了一串 "[read] I/O error: Read timed out" 后沒有進(jìn)行連接的重新建立,因此就報(bào)錯(cuò)了

那么可以通過打印 "[read] I/O error: Read timed out"日志的上下文日志縮小 排查代碼的范圍,上文日志 Connection request,下文日志 Connection leased,進(jìn)行代碼定位

image.png
image.png

基本上定位到了PooingHttpClientConnectionManager.java這個(gè)類,那么進(jìn)行代碼跟蹤吧

image.png

追蹤到了 AbstractConnPool.java類,那么這段代碼什么意思呢,這個(gè)就是進(jìn)行連接是否能夠復(fù)用的檢查代碼

對(duì)validateAfterInactivity進(jìn)行判斷,這個(gè)是服務(wù)器keep-alive的值

leasedEntry.getUpdated() + validateAfterInactivity <= System.currentTimeMillis():如果連接的最后一次使用時(shí)間 + 服務(wù)器keep-alive的時(shí)間 小于等于當(dāng)前時(shí)間,那么就認(rèn)為該連接可能已經(jīng)失效了
!validate(leasedEntry): 因此會(huì)進(jìn)行連接是否失效的檢查
跟進(jìn)去看看

image.png

最終找到"end of stream" and "[read] I/O error: Read timed out" 打印的地方
然后回到如下圖代碼:

image.png

可以看到

當(dāng)bytesRead 值為 -1 時(shí),返回true,那么HttpClient就會(huì)認(rèn)為該連接失效了,不能夠復(fù)用,并進(jìn)行清理操作,
當(dāng)拋出異常是ShockTimeoutException時(shí)會(huì)返回false, 那么HttpClient就會(huì)認(rèn)為該連接可復(fù)用

解決方案

禁用HttpClient的連接復(fù)用(有點(diǎn)扯淡)
重試方案:http請(qǐng)求使用重發(fā)機(jī)制,捕獲NohttpResponseException的異常,重新發(fā)送請(qǐng)求,重發(fā)3次后還是失敗才停止
根據(jù)keep Alive時(shí)間,調(diào)整validateAfterInactivity小于keepAlive Time,但這種方法依舊不能避免同時(shí)關(guān)閉
系統(tǒng)主動(dòng)檢查每個(gè)連接的空閑時(shí)間,并提前自動(dòng)關(guān)閉連接,避免服務(wù)端主動(dòng)斷開
推薦使用重試方案

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成,瀏覽時(shí)請(qǐng)結(jié)合常識(shí)與多方信息審慎甄別。
平臺(tái)聲明:文章內(nèi)容(如有圖片或視頻亦包括在內(nèi))由作者上傳并發(fā)布,文章內(nèi)容僅代表作者本人觀點(diǎn),簡書系信息發(fā)布平臺(tái),僅提供信息存儲(chǔ)服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容