解Bug之路-記一次調用外網服務機率性失敗問題的排查

前言

和外部聯調一直是使人困擾的問題，尤爲是一些基礎環境配置致使的問題。筆者在一次偶然狀況下解決了一個調用外網服務機率性失敗的問題。在此將排查過程發出來，但願讀者遇到此問題的時候，可以知道如何入手。

原由

筆者的新系統上線，須要PE執行操做。可是負責操做的PE確和另外一個開發在互相糾纏，讓筆者等了半個小時之久。本着加速系統上線的想法，就想着能不能幫他們快速處理掉問題，好讓筆者早點發完回去coding。一打聽，這個問題居然扯了3個月之久，問題現象以下:

每一個client都會以將近1/2的機率失敗,並且報錯都爲:

java.net.SocketTimeoutException: Read timed out

着手排查

和appserver開發以及對應的PE交流發現，appserver和nginx之間是短鏈接，因爲是socketTimeOutException,因而可以排除appserver和nginx創建鏈接之間的問題。去nginx上排查日誌，發現一個奇異的現象，以下圖所示:

全部的appserver都是調用一臺nginx一直成功，而調用另外一臺nginx大機率失敗。而兩臺nginx機器的配置如出一轍，還有一個奇怪的點是,只有在調用出問題的對端服務器時纔會失敗，其它業務沒有任何影響,以下圖所示:

因爲這兩個詭異的現象致使開發和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重傳後，對端就已經報錯。以下圖所示:

(注: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裏面,咱們繼續追蹤(如下代碼忽略了其它沒必要要的邏輯):

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:

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的話，系統是什麼表現:

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_rcvint 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的鏈接請求就會一直被丟棄。以下圖所示:

爲何對端自測一直正常

由於本機調用本機的時時間戳是一臺機器(本機)上的，因此不會出現混亂。

爲何nginx2調用其它服務是正常的

由於其它外部服務所在服務器並無開啓tcp_tw_recycle。這個問題事實上將tcp_tw_recycle置爲0也能夠解決。另外，高版本的linux內核已經去掉了tcp_tw_recycle這個參數。

總結

因爲當前ip地址緊缺和DNS報文大小的限制(512字節),大部分網絡架構都是採用NAT的方式去和外部交互，因此設置了tcp_tw_recycle爲1基本都會出現問題。通常這種問題須要對tcp協議有必定的瞭解纔可以順藤摸瓜找到最終的根源。