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

公司主營業(yè)務(wù)：成都網(wǎng)站建設(shè)、網(wǎng)站建設(shè)、移動網(wǎng)站開發(fā)等業(yè)務(wù)。幫助企業(yè)客戶真正實(shí)現(xiàn)互聯(lián)網(wǎng)宣傳，提高企業(yè)的競爭能力。成都創(chuàng)新互聯(lián)公司是一支青春激揚(yáng)、勤奮敬業(yè)、活力青春激揚(yáng)、勤奮敬業(yè)、活力澎湃、和諧高效的團(tuán)隊(duì)。公司秉承以“開放、自由、嚴(yán)謹(jǐn)、自律”為核心的企業(yè)文化，感謝他們對我們的高要求，感謝他們從不同領(lǐng)域給我們帶來的挑戰(zhàn)，讓我們激情的團(tuán)隊(duì)有機(jī)會用頭腦與智慧不斷的給客戶帶來驚喜。成都創(chuàng)新互聯(lián)公司推出阜寧免費(fèi)做網(wǎng)站回饋大家。

背景

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

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

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

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

現(xiàn)象

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

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

By case 排查，發(fā)現(xiàn)服務(wù) shard3 集群的機(jī)器報(bào) i/o timeout 錯誤。服務(wù)共有 4 個分片集群（根據(jù) ID hash 到對應(yīng)分片），其他 3 個集群完全正常。接著發(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)，開始慌了。

處理

上線出問題，第一時間回滾！

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

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

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

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

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

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

追查

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

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

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

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

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

進(jìn)一步查看提交記錄，發(fā)現(xiàn)在 2017 年 11 月份的時候有一次提交，修改了 vendor 文件夾里的代碼，但這時 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ì)比對代碼，主要差異在這：

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

只有 dump 數(shù)據(jù)文件這一個 goroutine 在干活，而且做的又是無限循環(huán)，服務(wù)整體對外表現(xiàn)就像是“死機(jī)”了一樣。并且這個 goroutine 由一個 timer 觸發(fā)工作，所以一開始我們看到的卡在一個 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ù)就是：“孫???雷”：

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

 
 
 
 

  
  
  
  
c == utf8.RuneError
  
  
  
  
size == 3
 
 
 
 

再看 RuneError 的定義：

 
 
 
 

  
  
  
  
const RuneError = '\\uFFFD'
 
 
 
 

看一下兩個版本的代碼不同之處：

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

最后就是找到異常數(shù)據(jù)到底屬于哪個計(jì)劃。我嘗試去每個集群的機(jī)器上，從數(shù)據(jù)文件里尋找“孫???雷”。但文件太大了，幾十個 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，就會查找整個文件，如果查到，則會有輸出；否則無。
3. 對于特別大的文件，可以先把 count 設(shè)為跳過一半文件大小的值，采用二分法查找。如果找到，則限定在了前半范圍，否則在后半部分。使用類似的方法繼續(xù)查找……
4. 如果找到，最后會輸出 count*bs 大小的內(nèi)容。

反思

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

網(wǎng)頁標(biāo)題：Go服務(wù)亂碼引發(fā)的線上事故
URL分享：http://www.5511xx.com/article/dhodihh.html