年前接到個任務,說要解決線上一些手機客戶端接口報錯率很高的問題.拿到了監控郵件,粗略一看,各種50%+的錯誤率,簡直觸目驚心.這種疑難雜症解決起來還是挺好玩的,於是擼起袖子action.
最終的結果雖然報錯問題得到了解決,但是感覺並不是最根本的解決方案.
下面把解決的過程和目前的問題放出來一起探討下.
第一步,針對錯誤進行跟蹤,初步定位問題
由於之前客戶端同學在請求中添加了唯一標示request_id. 所以選擇了一些報錯的記錄進行跟蹤. 打開了jetty的request_log請求日志,經查發現出錯請求會出現兩種情況:
1,未在request_log中出現,既請求都未能從nginx發送至后端服務
2,在request_log中出現,並返回成功(狀態碼200,並且響應時間很快)
由此暫時排除后端服務問題,推測問題出現在nginx與服務之間的鏈接.
第二步,查看nginx日志,初步優化
經由第一步得出結果,進一步觀察出錯時候的nginx日志.
發現出錯時nginx日志中會出現”no live upstreams while connecting to upstream”錯誤.並伴隨大量”upstream prematurely closed connection while reading response header from upstream”錯誤.
經查閱資料得出nginx負載與健康檢查機制的簡陋可能造成某些請求無法發送到活動的后端服務上. 遂添加nginx負載機制配置以期解決問題.
參考資料:
http://www.tuicool.com/articles/AfeuUje
https://segmentfault.com/a/1190000002446630
在線上backends中添加了以下配置:
備注: 因涉及服務器機密,IP及端口均經過修改
upstream mobile {
server 192.168.0.10:6001 max_fails=10 fail_timeout=10s;
server 192.168.0.10:6002 max_fails=10 fail_timeout=10s;
server 192.168.0.10:6003 max_fails=10 fail_timeout=10s;
server 192.168.0.10:6004 max_fails=10 fail_timeout=10s;
keepalive 64;
}
經過一段時間觀察后,發現"no live upstreams while connecting to upstream"錯誤大幅度減少,但502錯誤率依舊,依然存在大量"upstream prematurely closed connection while reading response header from upstream"
第三步,upstream prematurely closed connection while reading response header from upstream
添加第二步的配置后觀察與思考,推測問題可能出現在以下兩個方面:
1,后端jetty服務壓力過大導致無法完成響應.
2,網絡原因導致請求出問題.
那么一項一項的排查吧.
排除jetty服務壓力
先排查jetty服務壓力是否造成報錯.遂添加了對jetty線程及請求隊列的監控. 也引發了之前一篇關於jetty線程監控的文章.需要的朋友自行取用.
http://www.cnblogs.com/succour/p/6266283.html
觀察后發現即使高峰時期jetty中的線程數依然沒有過大壓力,沒有出現隊列擁堵現象.所以將重心放於網絡原因.
釋放招式:tcpdump抓包.網絡問題浮出水面.
進行tcp鏈接抓包並解析,分析出錯原因.
使用tcpdump抓包並解析后發現:
出錯請求都會在此tcp流中前一個請求未收到響應時就關閉鏈接
既一個tcp連接中的http請求與響應不能一一對應且請求數永遠比響應數多1.
而追蹤未出錯請求時則發現tcp流中請求與響應都可一一對應.
由於我們線上在nginx中都配置了nginx upstream中的keepalive,既nginx與后端服務鏈接的復用,推測可能是前一個請求結束后或keepalive時間到后nginx關閉了鏈接,而新的請求還在發送中就被中斷了.
第四步,去除keepalive配置,解決問題
在線上的upstream中去除了keepalive配置,配置變為了:
備注: 因涉及服務器機密,IP及端口均經過修改
upstream mobile {
server 192.168.0.10:6001 max_fails=10 fail_timeout=10s;
server 192.168.0.10:6002 max_fails=10 fail_timeout=10s;
server 192.168.0.10:6003 max_fails=10 fail_timeout=10s;
server 192.168.0.10:6004 max_fails=10 fail_timeout=10s;
}
修改生效當時那茫茫多的"upstream prematurely closed connection while reading response header from upstream"瞬間消失. 觀察了一天之后,502錯誤率明顯下降,現已下降到0.00x%的級別.
說明推測是正確的,nginx upstream的keeplive導致了此次問題的出現.
第五步,后續
雖然去除keepalive解決了問題,但是keepalive對於鏈接的復用確實是可以提高通信效率的.粗暴的刪除也只能是暫時的解決方案.而且也並沒有查閱到相關keepalive會引起此問題的文章.
所以問題的根源依舊沒有水落石出.
繼續推測可能是由於線上tcp鏈接的配置問題導致的.
於是將線上的tcp配置拷貝到測試環境,添加上keepalive對測試環境進行壓測,奇異的一幕出現了...問題並沒有被復現...
tcp配置參考資料:
http://www.cnblogs.com/zengkefu/p/5749009.html
一臉懵逼的我繼續觀察tcp抓到的包以及nginx中的錯誤日志...
終於是有所發現...
原來在nginx錯誤日志中以HTTP/1.1協議發送的請求,到了tcp抓包中竟然被悄悄改為了HTTP/1.0協議...並且Connection請求頭為close! nginx中所有報錯為"upstream prematurely closed connection while reading response header from upstream"的請求所抓到的包全部都是這種情況...
注意ip地址以及時間,確定與下圖為同一請求.
繼續觀察發現在這個被改變了http協議的請求前,都會有一個HTTP/1.0的請求.
然后對這個TCP流抓包,發現了下面的情況:
如圖,80為nginx服務器,72為后端jetty服務.
在80向72以tcp發送第一個get請求后,72以tcp回發了一個響應.這個響應中FIN標記是為0的,也就是不關閉連接.
80在接收到72的響應后,繼續以http發送了第二個get請求,也就是我們出錯的請求.而且此請求被改為了HTTP/1.0!
然后80解析了72回發的第一個get請求的響應,而這個響應的FIN標記被http協議標記為了1,也就是需要關閉連接了.
然后80就沒有等待第二個get請求的響應,發送了關閉連接的tcp報文.
此時第二個get請求也就沒有辦法發送響應了.因為tcp連接已經不存在了.
那么可以理解為HTTP/1.0協議發送的請求在請求結束后鏈接就被關閉,而在關閉前nginx依然復用了這個鏈接發送了請求...然后nginx關閉了連接,導致了后面這個請求報錯!
還有第一個get請求的響應中tcp到http這個"解析"過程是怎么回事,還有待查詢資料.問題就是在這個"解析"的時間內發送了另一個請求導致的...
至於第一個HTTP/1.0的請求是不是客戶端發送過來的1.0還是被nginx修改的1.0,今天我去查看日志的時候,發現日志被刪了...運維大哥今天又沒在...只能等他回來再驗證了...
未完待續...
有了結論:
據運維說不知道誰把nginx轉換http1.1的配置刪掉了...就是下面兩行:
proxy_http_version 1.1;
proxy_set_header Connection "";
雖然結論顯得有點中二...但是感覺排查問題的過程還是值得記錄的.