golang 服務大量 CLOSE_WAIT 故障排查

• 2020 年 2 月 13 日
• 筆記

• 事故經過
• 排查
• 總結

事故經過

【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）