解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				[TCP Retransmission]58850->443[SYN]
2019-07-25 16:45:44

由于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_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的連接配接請求就會一直被丢棄。如下圖所示:

為什麼對端自測一直正常

因為本機調用本機的時時間戳是一台機器(本機)上的，是以不會出現混亂。

為什麼nginx2調用其它服務是正常的

因為其它外部服務所在伺服器并沒有開啟tcp_tw_recycle。這個問題事實上将tcp_tw_recycle置為0也可以解決。另外，高版本的linux核心已經去掉了tcp_tw_recycle這個參數。

總結

由于目前ip位址緊缺和DNS封包大小的限制(512位元組),大部分網絡架構都是采用NAT的方式去和外部互動，是以設定了tcp_tw_recycle為1基本都會出現問題。一般這種問題需要對tcp協定有一定的了解才能夠順藤摸瓜找到最終的根源。