[[325047]]

最近遇到了一起依賴升級(jí) + 異常數(shù)據(jù)引發(fā)的線上事故，教訓(xùn)慘痛，本文對(duì)此進(jìn)行回故和總結(jié)。

背景

起因是我們使用的服務(wù)框架版本比較老，GC 次數(shù)的 metrics 打點(diǎn)一直為 0，咨詢了相關(guān)同學(xué)后，決定升級(jí)框架。升級(jí)的過程中，出現(xiàn)了 useofinternalpackagexxxnotallowed 的報(bào)錯(cuò)，又咨詢了一下相關(guān)同學(xué)后，嘗試使用 go mod 解決。

從 go vendor 到 go mod 的升級(jí)的過程也不太順利，這里按下不表，最終是升級(jí)成功了。一同升級(jí)的還有 Go 版本，從 1.11 升級(jí)到 1.13。

周四上完線后，一切都看似很不錯(cuò)：內(nèi)存占用、GC 消耗的 CPU 有了優(yōu)化，GC 次數(shù)的監(jiān)控也有了。因?yàn)樯婕暗焦緝?nèi)部數(shù)據(jù)，圖我就不放了。

周五、周六都平安度過，周日出問題了，小組的同學(xué)從下午 12 點(diǎn)左右一直肝到凌晨 12 點(diǎn)，才松了一口氣?？蓱z我們來之不易的一個(gè)周日！

現(xiàn)象

周日 11 點(diǎn) 45 左右，端口的調(diào)用失敗率報(bào)警，同時(shí)有業(yè)務(wù)方反饋調(diào)用接口報(bào)錯(cuò)。

同志們，關(guān)鍵時(shí)刻，完善的報(bào)警能給事故的處理和恢復(fù)贏得時(shí)間??！

By case 排查，發(fā)現(xiàn)服務(wù) shard3 集群的機(jī)器報(bào) i/o timeout 錯(cuò)誤。服務(wù)共有 4 個(gè)分片集群（根據(jù) ID hash 到對(duì)應(yīng)分片），其他 3 個(gè)集群完全正常。接著發(fā)現(xiàn) shard3 集群的機(jī)器內(nèi)存正常、端口還在，但 in/out 流量全部掉到幾十 KB/s，看日志也沒有發(fā)現(xiàn)任何異常。

重啟 shard3 集群的服務(wù)，重啟后的服務(wù)恢復(fù)正常，訪問 debug 端口，也是正常的。然而，十幾分鐘后，恢復(fù)的服務(wù)再次出現(xiàn)異常：in/out 流量再次掉到幾十 KB/s，訪問 debug 端口也沒有任何響應(yīng)，開始慌了。

處理

上線出問題，第一時(shí)間回滾！

穩(wěn)定性里面很重要的一條就是：有問題，先回滾。先止損，將事故影響降到最低，事后再來追查根因，總結(jié)復(fù)盤。

于是開始操作回滾， reset 到周四上線之前的一個(gè) commit，重新打包，上線 shard3 集群。之后，對(duì)外接口完全恢復(fù)，操作回滾其他集群。

服務(wù)啟動(dòng)之前，需要先加載幾十個(gè) G 左右的數(shù)據(jù)，啟動(dòng)過程長(zhǎng)達(dá) 10+ min。我申請(qǐng)了一臺(tái)線上問題機(jī)器的 root 權(quán)限，執(zhí)行了 strace-p 命令：

發(fā)現(xiàn)服務(wù)卡在 futex 系統(tǒng)調(diào)用上，這很明顯是一個(gè) timer，但是 timer 為何會(huì)卡??？正常情況下，會(huì)有各種像 write，read 的系統(tǒng)調(diào)用，至少打日志、上報(bào) mertrics 打點(diǎn)數(shù)據(jù)都會(huì)有 write 系統(tǒng)調(diào)用吧，哈？再執(zhí)行 perf top 命令：

相關(guān)的只有 codec 函數(shù)，再看服務(wù)進(jìn)程：

看 perf 輸出的結(jié)果，全部聚焦到 codec 這個(gè)第三方庫上，主要的兩個(gè)函數(shù)竟然是 codec.quoteStr 和 utf8.DecodeRuneInString。而我們用 codec 的地方是在程序啟動(dòng)時(shí)加載數(shù)據(jù)文件以及定時(shí)的 dump 文件到本地?，F(xiàn)在程序已經(jīng)啟動(dòng)了，只可能是 dump 文件出問題了。查看相關(guān)日志，果然有開始 dump 文件的日志記錄，卻一直沒有 dump 成功的記錄。

追查

事后追查階段嘗試在 test 集群上重現(xiàn)故障，因?yàn)橹挥袉蝹€(gè)分片出問題，說明此故障和特定數(shù)據(jù)有關(guān)，是 hash 到分片 3 的數(shù)據(jù)引起的問題。

又因?yàn)?test 集群并沒有分片，所以強(qiáng)行（改代碼 && 改環(huán)境變量）將其偽裝成 shard3 集群，然則并沒有復(fù)現(xiàn)，猜測(cè)可能是計(jì)劃下線了。

周二的時(shí)候，終于在 test 集群上模擬分片 1 時(shí)重現(xiàn)了線上故障。

對(duì)比 codec 的版本問題，果然有問題：周四上線前， vendor.json 里的版本是 v1.1.7，上線后，升級(jí)到了 v1.1.8，看來找到問題了！修改 codec 的版本，重新編譯、部署，問題依然存在！

這時(shí)，組里其他同學(xué)反饋 2018 年的時(shí)候也出過 codec 的問題，當(dāng)時(shí)也是出現(xiàn)了異常數(shù)據(jù)導(dǎo)致重啟時(shí)加載文件不成功。于是我直接將周四上線前 vendor 文件夾里 codec.quoteStr 函數(shù)的代碼和 codec 的 v1.1.7 代碼進(jìn)行對(duì)比，并不相同！vendor.json 里的版本并沒有正確反應(yīng) vendor 里實(shí)際的 codec 版本?。?！

進(jìn)一步查看提交記錄，發(fā)現(xiàn)在 2017 年 11 月份的時(shí)候有一次提交，修改了 vendor 文件夾里的代碼，但這時(shí) vendor.json 并沒有 codec 記錄。而在 2019 年 11 月的一次提交，則只在 vendor.json 里增加了一條 codec 記錄，vendor 文件夾里的代碼并沒有更改：

{ 
"checksumSHA1": "wfboMqCTVImg0gW31jvyvCymJPE=", 
"path": "github.com/ugorji/go/codec", 
"revision": "e118e2d506a6b252f6b85f2e2f2ac1bfed82f1b8", 
"revisionTime": "2019-07-23T09:17:30Z", 
"tree": true 
} 

仔細(xì)比對(duì)代碼，主要差異在這：

從現(xiàn)象及源碼看，大概率是在 codec.quoteStr 里死循環(huán)了！由于 Go 1.14 前都無法搶占正在執(zhí)行無限循環(huán)且沒有任何函數(shù)調(diào)用的 goroutine，因此一旦出現(xiàn)死循環(huán)，將要進(jìn)行 GC 的時(shí)候，其他所有 goroutine 都會(huì)停止，并且都在等著無限循環(huán)的 goroutine 停下來，遺憾的是，由于 for{} 循環(huán)里沒有進(jìn)行函數(shù)調(diào)用，無法插入搶占標(biāo)記并進(jìn)行搶占。于是，就出現(xiàn)了這樣一幕：

只有 dump 數(shù)據(jù)文件這一個(gè) goroutine 在干活，而且做的又是無限循環(huán)，服務(wù)整體對(duì)外表現(xiàn)就像是“死機(jī)”了一樣。并且這個(gè) goroutine 由一個(gè) timer 觸發(fā)工作，所以一開始我們看到的卡在一個(gè) futex 調(diào)用上就可以解釋得通。因?yàn)?runtime 都停止工作了，timer 自然就沒法“到期”了。

接著，使用 Go 1.14 去編譯有問題的代碼版本，上到 test 集群，果然問題“消失”。服務(wù)狀態(tài)完全恢復(fù)正常，唯一不正常的是數(shù)據(jù)文件無法 dump 下來了，因?yàn)榧词故?Go 1.14，也依然在執(zhí)行無限循環(huán)，不干“正事”。

接下來的問題就是找到異常的數(shù)據(jù)了。使用上線前的版本（使用 go vendor），將 codec 替換為最新的 v1.1.8 版本，并且在 quoteStr 函數(shù)里打上了幾行日志：

部署到 test 集群，問題復(fù)現(xiàn)：

異常數(shù)據(jù)就是：“孫���雷”：

為什么會(huì)引發(fā)死循環(huán)，在調(diào)用 utf8.DecodeRuneInString 函數(shù)后：

c == utf8.RuneError 
size == 3 

再看 RuneError 的定義：

const RuneError = '\\uFFFD' 

看一下兩個(gè)版本的代碼不同之處：

老版本的代碼，不會(huì)進(jìn)入 if 分支，而新版本的代碼，由于 c==utf8.RuneError，所以先進(jìn)入 if 分支，之后， size==3，不滿足里層分支，直接 continue 了，因此 i 值并沒有發(fā)生變化，死循環(huán)就這么發(fā)生了。

最后就是找到異常數(shù)據(jù)到底屬于哪個(gè)計(jì)劃。我嘗試去每個(gè)集群的機(jī)器上，從數(shù)據(jù)文件里尋找“孫���雷”。但文件太大了，幾十個(gè) G， grep 搞不定，沒關(guān)系，使用 dd 工具：

dd if=model_20200423155728 bs=1024 skip=3600000 count=1200 | grep '孫���雷' 

‍使用二分法找到了“孫���雷”！關(guān)于 dd+grep 的用法，總結(jié)了幾點(diǎn)：

1. 每次從文件開頭先跳過 skip*bs 大小的內(nèi)容，復(fù)制 count*bs 大小的內(nèi)容過來用 grep 查詢。
2. 如果不設(shè)置 count，就會(huì)查找整個(gè)文件，如果查到，則會(huì)有輸出；否則無。
3. 對(duì)于特別大的文件，可以先把 count 設(shè)為跳過一半文件大小的值，采用二分法查找。如果找到，則限定在了前半范圍，否則在后半部分。使用類似的方法繼續(xù)查找……
4. 如果找到，最后會(huì)輸出 count*bs 大小的內(nèi)容。

反思

1. 服務(wù)重大版本更新，至少在線下跑一周。
2. 有問題，第一時(shí)間回滾。
3. 對(duì)于工具的使用要規(guī)范。如不要隨意更改 vendor 文件夾的內(nèi)容而不同步更新 vendor.json 文件，反之亦然。
4. 因?yàn)?go mod 的版本選擇以及不遵守開源規(guī)范的第三方庫作者會(huì)讓使用者不知不覺、被動(dòng)地引入一些難以發(fā)現(xiàn)的問題。可以使用 go mod vendor 代替，如果要鎖死版本的話，使用 replace。