建站
咨詢
售后
建站咨詢
新聞中心
最近遇到了一起依賴升級(jí) + 異常數(shù)據(jù)引發(fā)的線上事故，教訓(xùn)慘痛，本文對(duì)此進(jìn)行回故和總結(jié)。
公司主營(yíng)業(yè)務(wù)：成都網(wǎng)站建設(shè)、網(wǎng)站建設(shè)、移動(dòng)網(wǎng)站開(kāi)發(fā)等業(yè)務(wù)。幫助企業(yè)客戶真正實(shí)現(xiàn)互聯(lián)網(wǎng)宣傳，提高企業(yè)的競(jìng)爭(zhēng)能力。成都創(chuàng)新互聯(lián)公司是一支青春激揚(yáng)、勤奮敬業(yè)、活力青春激揚(yáng)、勤奮敬業(yè)、活力澎湃、和諧高效的團(tuán)隊(duì)。公司秉承以“開(kāi)放、自由、嚴(yán)謹(jǐn)、自律”為核心的企業(yè)文化，感謝他們對(duì)我們的高要求，感謝他們從不同領(lǐng)域給我們帶來(lái)的挑戰(zhàn)，讓我們激情的團(tuán)隊(duì)有機(jī)會(huì)用頭腦與智慧不斷的給客戶帶來(lái)驚喜。成都創(chuàng)新互聯(lián)公司推出阜寧免費(fèi)做網(wǎng)站回饋大家。
背景
起因是我們使用的服務(wù)框架版本比較老，GC 次數(shù)的 metrics 打點(diǎn)一直為 0，咨詢了相關(guān)同學(xué)后，決定升級(jí)框架。升級(jí)的過(guò)程中，出現(xiàn)了 useofinternalpackagexxxnotallowed 的報(bào)錯(cuò)，又咨詢了一下相關(guān)同學(xué)后，嘗試使用 go mod 解決。
從 go vendor 到 go mod 的升級(jí)的過(guò)程也不太順利，這里按下不表，最終是升級(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ù)，圖我就不放了。
周五、周六都平安度過(guò)，周日出問(wèn)題了，小組的同學(xué)從下午 12 點(diǎn)左右一直肝到凌晨 12 點(diǎn)，才松了一口氣?？蓱z我們來(lái)之不易的一個(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í)間?。?/p>
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，看日志也沒(méi)有發(fā)現(xiàn)任何異常。
重啟 shard3 集群的服務(wù)，重啟后的服務(wù)恢復(fù)正常，訪問(wèn) debug 端口，也是正常的。然而，十幾分鐘后，恢復(fù)的服務(wù)再次出現(xiàn)異常：in/out 流量再次掉到幾十 KB/s，訪問(wèn) debug 端口也沒(méi)有任何響應(yīng)，開(kāi)始慌了。
處理
上線出問(wèn)題，第一時(shí)間回滾！
穩(wěn)定性里面很重要的一條就是：有問(wèn)題，先回滾。先止損，將事故影響降到最低，事后再來(lái)追查根因，總結(jié)復(fù)盤(pán)。
于是開(kāi)始操作回滾， reset 到周四上線之前的一個(gè) commit，重新打包，上線 shard3 集群。之后，對(duì)外接口完全恢復(fù)，操作回滾其他集群。
服務(wù)啟動(dòng)之前，需要先加載幾十個(gè) G 左右的數(shù)據(jù)，啟動(dòng)過(guò)程長(zhǎng)達(dá) 10+ min。我申請(qǐng)了一臺(tái)線上問(wèn)題機(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è)第三方庫(kù)上，主要的兩個(gè)函數(shù)竟然是 codec.quoteStr 和 utf8.DecodeRuneInString。而我們用 codec 的地方是在程序啟動(dòng)時(shí)加載數(shù)據(jù)文件以及定時(shí)的 dump 文件到本地?，F(xiàn)在程序已經(jīng)啟動(dòng)了，只可能是 dump 文件出問(wèn)題了。查看相關(guān)日志，果然有開(kāi)始 dump 文件的日志記錄，卻一直沒(méi)有 dump 成功的記錄。
追查
事后追查階段嘗試在 test 集群上重現(xiàn)故障，因?yàn)橹挥袉蝹€(gè)分片出問(wèn)題，說(shuō)明此故障和特定數(shù)據(jù)有關(guān)，是 hash 到分片 3 的數(shù)據(jù)引起的問(wèn)題。
又因?yàn)?test 集群并沒(méi)有分片，所以強(qiáng)行（改代碼 && 改環(huán)境變量）將其偽裝成 shard3 集群，然則并沒(méi)有復(fù)現(xiàn)，猜測(cè)可能是計(jì)劃下線了。
周二的時(shí)候，終于在 test 集群上模擬分片 1 時(shí)重現(xiàn)了線上故障。
對(duì)比 codec 的版本問(wèn)題，果然有問(wèn)題：周四上線前， vendor.json 里的版本是 v1.1.7，上線后，升級(jí)到了 v1.1.8，看來(lái)找到問(wèn)題了！修改 codec 的版本，重新編譯、部署，問(wèn)題依然存在！
這時(shí)，組里其他同學(xué)反饋 2018 年的時(shí)候也出過(guò) codec 的問(wèn)題，當(dāng)時(shí)也是出現(xiàn)了異常數(shù)據(jù)導(dǎo)致重啟時(shí)加載文件不成功。于是我直接將周四上線前 vendor 文件夾里 codec.quoteStr 函數(shù)的代碼和 codec 的 v1.1.7 代碼進(jìn)行對(duì)比，并不相同！vendor.json 里的版本并沒(méi)有正確反應(yīng) vendor 里實(shí)際的 codec 版本?。?！
進(jìn)一步查看提交記錄，發(fā)現(xiàn)在 2017 年 11 月份的時(shí)候有一次提交，修改了 vendor 文件夾里的代碼，但這時(shí) vendor.json 并沒(méi)有 codec 記錄。而在 2019 年 11 月的一次提交，則只在 vendor.json 里增加了一條 codec 記錄，vendor 文件夾里的代碼并沒(méi)有更改：
- {
- "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 前都無(wú)法搶占正在執(zhí)行無(wú)限循環(huán)且沒(méi)有任何函數(shù)調(diào)用的 goroutine，因此一旦出現(xiàn)死循環(huán)，將要進(jìn)行 GC 的時(shí)候，其他所有 goroutine 都會(huì)停止，并且都在等著無(wú)限循環(huán)的 goroutine 停下來(lái)，遺憾的是，由于 for{} 循環(huán)里沒(méi)有進(jìn)行函數(shù)調(diào)用，無(wú)法插入搶占標(biāo)記并進(jìn)行搶占。于是，就出現(xiàn)了這樣一幕：
只有 dump 數(shù)據(jù)文件這一個(gè) goroutine 在干活，而且做的又是無(wú)限循環(huán)，服務(wù)整體對(duì)外表現(xiàn)就像是“死機(jī)”了一樣。并且這個(gè) goroutine 由一個(gè) timer 觸發(fā)工作，所以一開(kāi)始我們看到的卡在一個(gè) futex 調(diào)用上就可以解釋得通。因?yàn)?runtime 都停止工作了，timer 自然就沒(méi)法“到期”了。
接著，使用 Go 1.14 去編譯有問(wèn)題的代碼版本，上到 test 集群，果然問(wèn)題“消失”。服務(wù)狀態(tài)完全恢復(fù)正常，唯一不正常的是數(shù)據(jù)文件無(wú)法 dump 下來(lái)了，因?yàn)榧词故?Go 1.14，也依然在執(zhí)行無(wú)限循環(huán)，不干“正事”。
接下來(lái)的問(wèn)題就是找到異常的數(shù)據(jù)了。使用上線前的版本（使用 go vendor），將 codec 替換為最新的 v1.1.8 版本，并且在 quoteStr 函數(shù)里打上了幾行日志：
部署到 test 集群，問(wèn)題復(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 值并沒(méi)有發(fā)生變化，死循環(huán)就這么發(fā)生了。
最后就是找到異常數(shù)據(jù)到底屬于哪個(gè)計(jì)劃。我嘗試去每個(gè)集群的機(jī)器上，從數(shù)據(jù)文件里尋找“孫???雷”。但文件太大了，幾十個(gè) G， grep 搞不定，沒(méi)關(guān)系，使用 dd 工具：
- dd if=model_20200423155728 bs=1024 skip=3600000 count=1200 | grep '孫???雷'
?使用二分法找到了“孫???雷”！關(guān)于 dd+grep 的用法，總結(jié)了幾點(diǎn)：
- 每次從文件開(kāi)頭先跳過(guò) skip*bs 大小的內(nèi)容，復(fù)制 count*bs 大小的內(nèi)容過(guò)來(lái)用 grep 查詢。
- 如果不設(shè)置 count，就會(huì)查找整個(gè)文件，如果查到，則會(huì)有輸出；否則無(wú)。
- 對(duì)于特別大的文件，可以先把 count 設(shè)為跳過(guò)一半文件大小的值，采用二分法查找。如果找到，則限定在了前半范圍，否則在后半部分。使用類似的方法繼續(xù)查找……
- 如果找到，最后會(huì)輸出 count*bs 大小的內(nèi)容。
反思
- 服務(wù)重大版本更新，至少在線下跑一周。
- 有問(wèn)題，第一時(shí)間回滾。
- 對(duì)于工具的使用要規(guī)范。如不要隨意更改 vendor 文件夾的內(nèi)容而不同步更新 vendor.json 文件，反之亦然。
- 因?yàn)?go mod 的版本選擇以及不遵守開(kāi)源規(guī)范的第三方庫(kù)作者會(huì)讓使用者不知不覺(jué)、被動(dòng)地引入一些難以發(fā)現(xiàn)的問(wèn)題?？梢允褂?go mod vendor 代替，如果要鎖死版本的話，使用 replace。
當(dāng)前名稱：Go服務(wù)亂碼引發(fā)的線上事故
網(wǎng)站網(wǎng)址：http://fisionsoft.com.cn/article/dhodihh.html
