1. 程式人生 > >解Bug之路-記一次呼叫外網服務概率性失敗問題的排查

解Bug之路-記一次呼叫外網服務概率性失敗問題的排查

# 解Bug之路-記一次呼叫外網服務概率性失敗問題的排查 ## 前言 和外部聯調一直是令人困擾的問題,尤其是一些基礎環境配置導致的問題。筆者在一次偶然情況下解決了一個呼叫外網服務概率性失敗的問題。在此將排查過程發出來,希望讀者遇到此問題的時候,能夠知道如何入手。 ## 起因 筆者的新系統上線,需要PE執行操作。但是負責操作的PE確和另一個開發在互相糾纏,讓筆者等了半個小時之久。本著加速系統上線的想法,就想著能不能幫他們快速處理掉問題,好讓筆者早點發完回去coding。一打聽,這個問題竟然扯了3個月之久,問題現象如下: ![](https://oscimg.oschina.net/oscnet/158c26fc92721b37c80c16a2270a5d4681f.jpg) 每個client都會以將近1/2的概率失敗,而且報錯都為: ```java java.net.SocketTimeoutException: Read timed out ``` ## 著手排查 和appserver開發以及對應的PE交流發現,appserver和nginx之間是短連線,由於是socketTimeOutException,於是能夠排除appserver和nginx建立連線之間的問題。去nginx上排查日誌,發現一個奇異的現象,如下圖所示: ![](https://oscimg.oschina.net/oscnet/47642234092b2aaf3d1b6d03d0384702c47.jpg) 所有的appserver都是呼叫一臺nginx一直成功,而呼叫另一臺nginx大概率失敗。而兩臺nginx機器的配置一模一樣,還有一個奇怪的點是,只有在調用出問題的對端伺服器時才會失敗,其它業務沒有任何影響,如下圖所示: ![](https://oscimg.oschina.net/oscnet/d1764fc9736b7792bdcb8a5dcf2407e0c94.jpg) 由於這兩個詭異的現象導致開發和PE爭執不下,按照第一個現象一臺nginx好一臺nginx報錯那麼第二臺nginx有問題是合理的推斷,所以開發要求換nginx。按照第二個現象,只有呼叫這個業務才會出錯,其它業務沒有問題,那麼肯定是對端業務伺服器的問題,PE覺得應該不是nginx的鍋。爭執了半天后,初步擬定方案就是擴容nginx看看效果-_-!筆者覺得這個方案並不靠譜,盲目的擴容可能會引起反效果。還是先抓包看看情況吧。 ## 抓包 其實筆者覺得nginx作為這麼通用的元件不應該出現問題,問題應該出現在對端伺服器上。而根據對端開發反應,他自己curl沒問題,並現場在他自己的伺服器上做了N次curl也沒有任何問題(由於這個問題僵持不下,他被派到我們公司來協助排查)。於是找網工在防火牆外抓包,抓包結果如下: |時間點|源ip|目的ip|協議|info| |:---|:---|:---|:---|:---| |2019-07-25 16:45:41|20.1.1.1|30.1.1.1|tcp|58850->443[SYN]| |2019-07-25 16:45:42|20.1.1.1|30.1.1.1|tcp|\[TCP Retransmission\]58850->443\[SYN\]| |2019-07-25 16:45:44|20.1.1.1|30.1.1.1|tcp|\[TCP Retransmission\]58850->443\[SYN\]| 由於appserver端設定的ReadTimeOut超時時間是3s,所以在2次syn重傳後,對端就已經報錯。如下圖所示: ![](https://oscimg.oschina.net/oscnet/0f3803422477a2b2ccb24aa5db5a0b0bdc0.jpg) (注:nginx所在linux伺服器設定的tcp\_syn\_retries是2) ## 抓包結果分析 從抓包得出的資料來看,第二臺nginx傳送syn包給對端服務,對端服務沒有任何響應,導致了nginx2建立連線超時,進而導致了appserver端的ReadTimeOut超時(appserver對nginx是短連線)。 按照正常推論,應該是防火牆外到對端服務的SYN丟失了。而阿里雲作為一個非常穩定的服務商,應該不可能出現如此大概率的丟失現象。而從對端伺服器用的是非常成熟的SpringBoot來看,也不應該出現這種bug。那麼最有可能的就是對端伺服器本身的設定有問題。 ## 登陸對端伺服器進行排查 由於對方的開發來到了現場,於是筆者就直接用他的電腦登入了服務所在的阿里雲伺服器。首先看了下dmesg,如下圖所示,有一堆報錯: ``` dmesg: __ratelimit: 33491 callbacks suppressed TCP: time wait bucket table overflow TCP: time wait bucket table overflow TCP: time wait bucket table overflow ...... ``` 感覺有點關聯,但是僅靠這個資訊無法定位問題。緊接著,筆者運行了下netstat -s: ``` netstat -s ...... 16990 passive connections rejected because of time stamp ...... ``` 這條命令給出了非常關鍵的資訊,翻譯過來就是有16990個被動連線由於時間戳(time stamp)而拒絕!查了下資料發現這是由於設定了 ``` tcp_timestamps == 1 && tcp_tw_recycle == 1 ``` 在NAT情況下將會導致這個被動拒絕連線的問題。而為解決上面的dmesg日誌,網上給出的解決方案就是設定tcp\_tw\_recycle=1而tcp\_timestamps預設就是1,同時我們的客戶端呼叫也是從NAT出去的,符合了這個問題的所有特徵。 於是筆者嘗試著將他們的tcp\_timestamps設為0, ``` echo '0' > /proc/sys/net/ipv4/tcp_timestamps or echo '0' > /proc/sys/net/ipv4/tcp_tw_recycle ``` 又做了幾十次呼叫,再也沒有任何報錯了! ## linux原始碼分析 問題雖然解決了,但是筆者想從原始碼層面看一看這個問題到底是怎麼回事,於是就開始研究對應的原始碼(基於linux-2.6.32原始碼)。 由於問題是發生在nginx與對端伺服器第一次握手(即傳送第一個syn)的時候,於是我們主要跟蹤下這一處的相關原始碼: ``` // 三次握手第一個SYN kernel走的分支 tcp_v4_do_rcv |->tcp_v4_hnd_req |->tcp_rcv_state_process /** case TCP_LISTEN && th->syn */ |->conn_request(tcp_v4_conn_request) ``` 關於tcp\_timestamps的程式碼就在tcp\_v4\_conn\_request裡面,我們繼續追蹤(以下程式碼忽略了其它不必要的邏輯): ```c int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb) { ...... /* VJ's idea. We save last timestamp seen * from the destination in peer table, when entering * state TIME-WAIT, and check against it before * accepting new connection request. * 註釋大意為: * 我們在進入TIME_WAIT狀態的時候將最後的時間戳記錄到peer tables中, * 然後在新的連線請求進來的時候檢查這個時間戳 */ // 在tcp_timestamps和tcp_tw_recycle開啟的情況下 if (tmp_opt.saw_tstamp && tcp_death_row.sysctl_tw_recycle && (dst = inet_csk_route_req(sk, req)) != NULL && (peer = rt_get_peer((struct rtable *)dst)) != NULL && peer->v4daddr == saddr) { /** TCP_PAWS_MSL== 60 */ /** TCP_PAWS_WINDOW ==1 */ // 以下都是針對同一個對端ip // tcp_ts_stamp 對端ip的連線進入time_wait狀態後記錄的本機時間戳 // 當前時間在上一次進入time_wait記錄的實際戳後的一分鐘之內 if (get_seconds() < peer->tcp_ts_stamp + TCP_PAWS_MSL && // tcp_ts 最近接收的那個資料包的時間戳(對端帶過來的) // 對端當前請求帶過來的時間戳小於上次記錄的進入time_wait狀態後記錄的對端時間戳 (s32)(peer->tcp_ts - req->ts_recent) > TCP_PAWS_WINDOW) { // 增加被動連線拒絕的統計資訊 NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_PAWSPASSIVEREJECTED); // 進入丟棄和釋放階段 goto drop_and_release; } } ...... } ``` 上述程式碼的核心意思即是在tcp\_timestamps和tcp\_tw_recycle開啟的情況下,同樣ip的連線,在上個連線進入time\_wait狀態的一分鐘內,如果有新的連線進來,而且新的連線的時間戳小於上個進入time\_wait狀態的最後一個包的時間戳,則將這個syn丟棄,進入drop\_and\_release。我們繼續跟蹤drop\_and\_release: ```c int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb){ ...... drop_and_release: dst_release(dst); drop_and_free: reqsk_free(req); drop: return 0; } ``` 我們繼續看下如果tcp\_v4\_conn\_request返回0的話,系統是什麼表現: ```c int tcp_rcv_state_process(struct sock *sk, struct sk_buff *skb, struct tcphdr *th, unsigned len) { ...... // 由於tcp_v4_conn_request所以不走下列分枝 if (icsk->icsk_af_ops->conn_request(sk, skb) < 0) return 1 // 所以此處也返回0 kfree_skb(skb); return 0; } // 再跳回tcp_v4_do_rcv int tcp_v4_do_rcv(struct sock *sk, struct sk_buff *skb) { // 由於tcp_rcv_state_process這邊返回的是0,所以不走reset的邏輯 if (tcp_rcv_state_process(sk, skb, tcp_hdr(skb), skb->len)) { rsk = sk; goto reset; } // 走到這邊之後,不傳送reset包,不給對端任何響應 TCP_CHECK_TIMER(sk); return 0; } ``` 從原始碼的跟蹤可以看出,出現此種情況直接丟棄對應的syn包,對端無法獲得任何響應從而進行syn重傳,這點和抓包結果一致。 ## 和問題表象一一驗證 ### 為什麼會出現一臺nginx一直okay,一臺nginx失敗的情況 由於tcp的時間戳是指的並不是當前本機用date命令給出的時間戳。這個時間戳的計算規則就在這裡不展開了,只需要知道每臺機器的時間戳都不相同即可(而且相差可能極大)。由於我們呼叫對端採用的是NAT,所以兩臺nginx在對端伺服器看來是同一個ip,那麼這兩臺的時間戳傳送到對端伺服器的時候就會混亂。nginx1的時間戳比nginx2的時間戳大,所以在一分鐘之內,只要出現nginx1的連線請求(短連線),那麼之後的nginx2的連線請求就會一直被丟棄。如下圖所示: ![](https://oscimg.oschina.net/oscnet/6b4d6ff59ba066dac0f136d848b3d77ec4d.jpg) ### 為什麼對端自測一直正常 因為本機呼叫本機的時時間戳是一臺機器(本機)上的,所以不會出現混亂。 ### 為什麼nginx2呼叫其它服務是正常的 因為其它外部服務所在伺服器並沒有開啟tcp\_tw\_recycle。這個問題事實上將tcp\_tw\_recycle置為0也可以解決。另外,高版本的linux核心已經去掉了tcp\_tw\_recycle這個引數。 ## 總結 由於當前ip地址緊缺和DNS報文大小的限制(512位元組),大部分網路架構都是採用NAT的方式去和外部互動,所以設定了tcp\_tw\_recycle為1基本都會出現問題。一般這種問題需要對tcp協議有一定的瞭解才能夠順藤摸瓜找到最終的根源。 ## 公眾號 關注筆者公眾號,獲取更多幹貨文章: ![](https://oscimg.oschina.net/oscnet/up-03e8bdd592b3eb9dec0a50fa5ff56192df0.JPEG)