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

2021-10-04 09:56:34 字數 3663 閱讀 6475

和外部聯調一直是令人困擾的問題,尤其是一些基礎環境配置導致的問題。筆者在一次偶然情況下解決了乙個呼叫外網服務概率性失敗的問題。在此將排查過程發出來,希望讀者遇到此問題的時候,能夠知道如何入手。

起因筆者的新系統上線,需要pe執行操作。但是負責操作的pe確和另乙個開發在互相糾纏,讓筆者等了半個小時之久。本著加速系統上線的想法,就想著能不能幫他們快速處理掉問題,好讓筆者早點發完回去coding。

一打聽,這個問題竟然扯了3個月之久,問題現象如下:

每個client都會以將近1/2的概率失敗,而且報錯都為:

著手排查

由於這兩個詭異的現象導致開發和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]

如下圖所示:

(注:nginx所在linux伺服器設定的tcp_syn_retries是2)

抓包結果分析

按照正常推論,應該是防火牆外到對端服務的syn丟失了。而阿里雲作為乙個非常穩定的服務商,應該不可能出現如此大概率的丟失現象。而從對端伺服器用的是非常成熟的springboot來看,也不應該出現這種bug。那麼最有可能的就是對端伺服器本身的設定有問題。

登陸對端伺服器進行排查

由於對方的開發來到了現場,於是筆者就直接用他的電腦登入了服務所在的阿里雲伺服器。首先看了下dmesg,如下圖所示,有一堆報錯:

感覺有點關聯,但是僅靠這個資訊無法定位問題。緊接著,筆者執行了下netstat -s:

這條命令給出了非常關鍵的資訊,翻譯過來就是有16990個被動連線由於時間戳(time stamp)而拒絕!查了下資料發現這是由於設定了

在nat情況下將會導致這個被動拒絕連線的問題。而為解決上面的dmesg日誌,網上給出的解決方案就是設定tcp_tw_recycle=1而tcp_timestamps預設就是1,同時我們的客戶端呼叫也是從nat出去的,符合了這個問題的所有特徵。於是筆者嘗試著將他們的tcp_timestamps設為0。

又做了幾十次呼叫,再也沒有任何報錯了!

linux原始碼分析

問題雖然解決了,但是筆者想從原始碼層面看一看這個問題到底是怎麼回事,於是就開始研究對應的原始碼(基於linux-2.6.32原始碼)。由於問題是發生在nginx與對端伺服器第一次握手(即傳送第乙個syn)的時候,於是我們主要跟蹤下這一處的相關原始碼:

關於tcp_timestamps的**就在tcp_v4_conn_request裡面,我們繼續追蹤(以下**忽略了其它不必要的邏輯):

int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb)

}

......

}

上述**的核心意思即是在tcp_timestamps和tcp_tw_recycle開啟的情況下,同樣ip的連線,在上個連線進入time_wait狀態的一分鐘內,如果有新的連線進來,而且新的連線的時間戳小於上個進入time_wait狀態的最後乙個包的時間戳,則將這個syn丟棄,進入drop_and_release。

我們繼續跟蹤drop_and_release:

我們繼續看下如果tcp_v4_conn_request返回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協議有一定的了解才能夠順藤摸瓜找到最終的根源。

網絡卡變慢 解Bug之路記一次線上請求偶爾變慢的排查

最近解決了個比較棘手的問題,由於排查過程挺有意思,於是就以此為素材寫出了本篇文章。這是乙個偶發的效能問題。在每天幾百萬比交易請求中,平均耗時大約為300ms,但總有那麼100多筆會超過1s,讓我們業務耗時監控的99.99線變得很尷尬。如下圖所示 為了精益求精,更為了消除這個尷尬的指標,筆者開始探尋起...

Flash,一次Bug的思考

我絕對不算是f黑,大部分時候,我還是很挺flash平台的,flash提供了很好的跨平台特性以及flash player11後的gpu加速 stage3d等等,對於開發者來說,絕對讓人欣喜若狂 對我是這樣 flash出bug也算是常有的事,不過大都還好,我能理解adobe開發者們的辛苦,要考慮跨平台 ...

一次不該出現的bug

部門好久沒有出過事件了,ps 事件可以簡單的理解為bug,事件分為5個類別,其中嚴重的是1級,災難性的。但是這次是天災,避免不了。首先說說我們發布程式的過程,首先程式設計師發布到測試環境,測試人員測試通過,然後發布到uat,業務人員接著測,這個地方其實是很薄弱的,uat環境缺失很多資料,有的地方根本...