golang 服務大量 CLOSE_WAIT 故障排查

• 事故通過
• 排查
• 總結

事故通過

【2019-12-27 18:00 週五】
業務方忽然找來講調用咱們程序大量提示「觸發限流」，可是咱們沒有收到任何監控報警。緊急查看了下 ServiceMesh sidecar 代理監控發現流量持續在減小，可是監控中沒有任何觸發限流的 http code 429 佔比，若是有觸發限流咱們會收到報警。

後來經過排查是程序中有一個歷史限流邏輯觸發了，可是程序中觸發限流返回的 http code 是 200，這就徹底避開了 sidecar http code 非200 異常指標監控報警。把代碼中的限流閾值調了很是大的一個值，統一走 sidecar 限流爲準。

猜想本次觸發限流可能跟網路抖動有關係，網絡抖動致使鏈接持續被佔用，最終 qps 超過限流閾值。由於這個程序最近都沒有發佈過，再加上業務上也沒有突發流量，一切都很常態化。

【2019-12-28 15:30 週六】
相同的問題次日悄無聲息的又出現了，仍是業務請求量持續下掉，上游業務方仍是提示「觸發限流」，同時業務監控環比也在逐步下掉。

以恢復線上問題爲第一原則快速重啓了程序，線上恢復。

修改了代碼，去掉了限流邏輯，就算觸發限流也應該第一時間告警出來，這段代碼返回 http 200 就很坑了，咱們徹底無感知。雖然咱們知道觸發限流是「果」，「因」咱們並不知道，可是故障要在第一時間暴露出來纔是最重要的。

咱們知道這個問題確定還會出現，要讓隱藏的問題儘量的所有暴露出來，用最快最小的代價發現和解決掉纔是正確的方式。

恢復線上問題以後，開始排查相關係統指標，首先排查程序依賴的 DB、redis 等中間件，各項指標都很正常，DB 鏈接池也很正常，活動鏈接數個位數，redis 也是。故障期間相關中間件、網絡流量均出現 _qps_降低的狀況。

當時開始排查網絡抖動狀況，可是仔細排查以後也沒有出現丟包等狀況。（仔細思考下，其實網絡問題有點不合邏輯，由於相鄰兩天不可能同時觸發同一條鏈路上的網絡故障，並且其餘系統都很正常。）

【2019-12-28 22:48 週六】
此次觸發了 sidecar http code 非200佔比 告警，咱們第一時間恢復了，整個告警到恢復只用了幾分鐘不到，將業務方的影響減小到最低。

可是因爲缺乏請求鏈路中間環節日誌，很難定位究竟是哪裏出現問題。此次咱們打開了 sidecar 的請求日誌，觀察請求的日誌，等待下次觸發。(因爲 qps 較高，默認是不打開 sidecar 請求日誌)

同時請運維、基礎架構、DBA、雲專家等開始仔細排查整個鏈路。查看機器監控，發現故障期間 socket fd 升高到了3w多，隨着fd升高內存也在持續佔用，可是遠沒有到系統瓶頸，DB、redis 仍是出現故障窗口期間 qps 同步下掉的狀況。

這個程序是兩臺機器，出故障只有一臺機器，週五和週六分別是兩臺機器交替出現 hang 住的狀況。可是因爲沒有保留現場，沒法仔細分析。（之因此不能直接下掉一臺機器保留現場，是由於有些業務調用並不徹底走 sidecar，有些仍是走的域名進行調用。因此沒法乾淨的下掉一臺機器排查。）

socket fd 升高暫不肯定是什麼緣由形成的。此次已經作好準備，下次故障當即 dump 網路鏈接，步步逼近問題。

【2019-12-29 18:34 週日】
就在咱們排查的此時兩臺機器先後炸了一遍，迅速 netstat 下鏈接信息，而後重啓程序，如今終於有了一些線索。

回顧整個故障過程，因爲咱們沒法短期內定位到，可是咱們必須轉被動爲主動。從原來被動接受通知，到主動發現，讓問題第一時間暴露出來，快速無感知恢復線上，而後逐步經過各類方式方法慢慢定位。

不少時候，咱們排查問題會陷入細節，忽視了線上故障時間，應該以先恢復爲第一原則。（故障等級和時間是正比的）

排查

【netstat 文件分析】
到目前爲止發現問題沒有那麼簡單，咱們開始有備而來，主動揪出這個問題的時候了。作好相應的策略抓取更多的現場信息分析。分析了 netstat 導出來的鏈接信息。

tcp6       0      0 localhost:synapse-nhttp localhost:56696         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:60666         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:39570         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:55682         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:36812         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:58454         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:43694         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:32928         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:60710         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:33418         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:36980         CLOSE_WAIT

一時矇蔽，synapse-nhttp 這個是什麼程序，當時不肯定全是 tcp 網絡鏈接的 fd，情急之下只顧着導出最全的網絡信息執行了 netstat -a ，沒有帶上 -n -p 轉換端口爲數字同時輸出執行程序。~_~

這個 synapse-nhttp 很是可疑，同時查看了其餘 go 程序機器都沒有這個鏈接，爲了排查是否程序自己問題，查看了 pre、qa 機器的鏈接，均都是 synapse-nhttp 這個端口名字。

判斷下來 synapse-nhttp 確實是咱們本身的程序，可是爲何端口名字會是 synapse-nhttp，後來查詢下來發現咱們程序使用的 8280 端口就是 synapse-nhttp 默認端口，因此被 netstat 自動人性化解析了。~_~

因爲請求鏈路通過 sidecar 進來，大量的 CLOSE_WAIT 被動關閉狀態，開始懷疑 sidecar 問題，保險起見咱們採用排除法先將一個機器的量切到走域名作灰度測試，看是 sidecar 問題仍是程序自己問題。

咱們發現一個有意思的現象，CLOSE_WAIT 是被動關閉鏈接的狀態，主動關閉鏈接的狀態應該是 FIN_WAIT1。比較了兩種狀態鏈接數不是一個數量級，CLOSE_WAIT 將近1w個，而 FIN_WAIT1 只有幾個，同時 FIN_WAIT2 只有幾十個，TIME_WAIT一個沒有。

合理狀況下，sidecar 鏈接的 FIN_WAIT1 狀態和本機程序鏈接的 CLOSE_WAIT 狀態應該是一個數量級纔對。可是如今明顯被動關閉並無成功完成，要麼是上游 sidecar 主動斷開了鏈接，本機程序遲遲未能發送 fin ack，sidecar 端的鏈接被 tcp keepalive 保活關閉釋放了。或者本機程序已經發出 fin ack 可是 sidecar 沒有收到，還有一種可能就是，sidecar 端鏈接在收到 fin ack 前被回收了。

固然，這些只是猜想，爲了搞清楚具體什麼緣由致使只能抓包看 tcp 交互才能得出最終結論。

【tcpdump 包分析】
咱們準備好 tcpdump 腳本，按期抓取 tcp 包，如今就在等故障出現了，由於故障必定還會出現。果真在30號下午又出現了，咱們一陣激動準備分析dump文件，可是端口抓錯了，sidecar 和程序都是本機調用走的是本地環回 lo 虛擬網卡接口，調整腳本在耐心的等待。~_~

問題又如期而至，咱們開始分析包。

能夠很清楚看到 HTTP 請求有進來沒有返回的。第一個紅框是請求超時，上游主動關閉鏈接，超時時間大概是1s，服務器正常返回了 fin ack。第二個紅框大概是間隔了一分半鐘，主動關閉鏈接，可是直接返回 RST 重置標誌，原先的鏈接其實已經不存在了。

爲了驗證這個請求爲何沒有返回，咱們提取 tcpdump 中的 HTTP 請求到後端日誌查看發現到了服務器，咱們再從 Mysql 服務器請求 sql 中查看發現沒有這個請求沒有進來，同時咱們發現一個規律，故障期間 DB 非活動鏈接數都有持續跑高現象，很是規律。

基本上判定是 DB 鏈接池泄漏，開始排查代碼。

發現代碼中有一個方法有問題，這個方法以前一直沒有業務規則命中，故障前一天26號有一個業務方開始走到這個方法。這個方法有一個隱藏bug，會致使 go 鏈接沒法關閉。

這個bug其實也有go.sql原生庫的一半責任。

var r *sql.Rows
    if r, err = core.GetDB().NewSession(nil).SelectBySql(query).Rows(); err != nil {
        return
    }

    for r.Next() {
        if err = r.Scan(&sum); err != nil {
            applog.Logger.Error(fmt.Sprint("xxx", err))
            r.Close() // 因爲沒有主動close鏈接致使泄漏
            return
        }
    }

sql.Rows 的Scan方法內部因爲沒有判斷查詢DB返回的空，就直接轉換致使 converting panic 。在加上咱們這個方法沒有處理 panic 狀況，因此命中隱藏bug就會泄漏。

這個方法爲何不主動關閉鏈接是由於 sql.Rows 掃描到最後會作關閉動做，因此一直以來都很好。

因此真正的問題是因爲 鏈接池泄漏，致使全部的請求 goroutine block 在獲取鏈接地方的地方，這一類問題排查起來很是困難。

總結

1.回顧這整個排查過程，我以爲讓系統運行的健康狀態透明化纔是發現問題的最有效手段，代碼不出問題不現實。

2._go.sql_ 庫還談不上企業級應用，整個鏈接消耗、空閒和工做時長都是沒有監控的，這也是致使這個case沒法快速定位的緣由。包括go的其餘方面都存在不少不完善的地方，尤爲是企業級應用套件都很弱，包括_go_原生 dump 內存以後分析的套件。

3.整個排查仍是受到了一些噪音干擾，沒能堅決核心邏輯和理論。DB 鏈接跑高爲何沒注意到，這一點實際上是由於咱們通常只看當時故障先後半小時後指標，沒有拉長看最近一段時間規律是否有異樣，包括 sidecar 流量持續下掉是由於都是存量請求，請求逐漸被 _hang_住，致使量持續下掉，因此看上去感受請求變少了，由於並無多出流量。

4.其實線上故障一旦被定位以後，問題自己都很簡單，一行不起眼的代碼而已。因此咱們必須敬畏每一行代碼。

做者：王清培（趣頭條 Tech Leader）