“���”引发的线上事故

最近遇到了一起依赖升级 + 异常数据引发的线上事故，教训惨痛，本文对此进行回故和总结。

背景

起因是我们使用的服务框架版本比较老，GC 次数的 metrics 打点一直为 0，咨询了相关同学后，决定升级框架。升级的过程中，出现了 useofinternalpackagexxxnotallowed 的报错，又咨询了一下相关同学后，尝试使用 go mod 解决。

从 go vendor 到 go mod 的升级的过程也不太顺利，这里按下不表，最终是升级成功了。一同升级的还有 Go 版本，从 1.11 升级到 1.13。

周四上完线后，一切都看似很不错：内存占用、GC 消耗的 CPU 有了优化，GC 次数的监控也有了。因为涉及到公司内部数据，图我就不放了。

周五、周六都平安度过，周日出问题了，小组的同学从下午 12 点左右一直肝到凌晨 12 点，才松了一口气。可怜我们来之不易的一个周日！

现象

周日 11 点 45 左右，端口的调用失败率报警，同时有业务方反馈调用接口报错。

同志们，关键时刻，完善的报警能给事故的处理和恢复赢得时间啊！

By case 排查，发现服务 shard3 集群的机器报 i/o timeout 错误。服务共有 4 个分片集群（根据 ID hash 到对应分片），其他 3 个集群完全正常。接着发现 shard3 集群的机器内存正常、端口还在，但 in/out 流量全部掉到几十 KB/s，看日志也没有发现任何异常。

重启 shard3 集群的服务，重启后的服务恢复正常，访问 debug 端口，也是正常的。然而，十几分钟后，恢复的服务再次出现异常：in/out 流量再次掉到几十 KB/s，访问 debug 端口也没有任何响应，开始慌了。

处理

上线出问题，第一时间回滚！

稳定性里面很重要的一条就是：有问题，先回滚。先止损，将事故影响降到最低，事后再来追查根因，总结复盘。

于是开始操作回滚， reset 到周四上线之前的一个 commit，重新打包，上线 shard3 集群。之后，对外接口完全恢复，操作回滚其他集群。

服务启动之前，需要先加载几十个 G 左右的数据，启动过程长达 10+ min。我申请了一台线上问题机器的 root 权限，执行了 strace-p 命令：

发现服务卡在 futex 系统调用上，这很明显是一个 timer，但是 timer 为何会卡住？正常情况下，会有各种像 write，read 的系统调用，至少打日志、上报 mertrics 打点数据都会有 write 系统调用吧，哈？再执行 perf top 命令：

相关的只有 codec 函数，再看服务进程：

看 perf 输出的结果，全部聚焦到 codec 这个第三方库上，主要的两个函数竟然是 codec.quoteStr 和 utf8.DecodeRuneInString。而我们用 codec 的地方是在程序启动时加载数据文件以及定时的 dump 文件到本地。现在程序已经启动了，只可能是 dump 文件出问题了。查看相关日志，果然有开始 dump 文件的日志记录，却一直没有 dump 成功的记录。

追查

事后追查阶段尝试在 test 集群上重现故障，因为只有单个分片出问题，说明此故障和特定数据有关，是 hash 到分片 3 的数据引起的问题。

又因为 test 集群并没有分片，所以强行（改代码 && 改环境变量）将其伪装成 shard3 集群，然则并没有复现，猜测可能是计划下线了。

周二的时候，终于在 test 集群上模拟分片 1 时重现了线上故障。

对比 codec 的版本问题，果然有问题：周四上线前， vendor.json 里的版本是 v1.1.7，上线后，升级到了 v1.1.8，看来找到问题了！修改 codec 的版本，重新编译、部署，问题依然存在！

这时，组里其他同学反馈 2018 年的时候也出过 codec 的问题，当时也是出现了异常数据导致重启时加载文件不成功。于是我直接将周四上线前 vendor 文件夹里 codec.quoteStr 函数的代码和 codec 的 v1.1.7 代码进行对比，并不相同！vendor.json 里的版本并没有正确反应 vendor 里实际的 codec 版本！！！

进一步查看提交记录，发现在 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



}

仔细比对代码，主要差异在这：

从现象及源码看，大概率是在 codec.quoteStr 里死循环了！由于 Go 1.14 前都无法抢占正在执行无限循环且没有任何函数调用的 goroutine，因此一旦出现死循环，将要进行 GC 的时候，其他所有 goroutine 都会停止，并且都在等着无限循环的 goroutine 停下来，遗憾的是，由于 for{} 循环里没有进行函数调用，无法插入抢占标记并进行抢占。于是，就出现了这样一幕：

只有 dump 数据文件这一个 goroutine 在干活，而且做的又是无限循环，服务整体对外表现就像是“死机”了一样。并且这个 goroutine 由一个 timer 触发工作，所以一开始我们看到的卡在一个 futex 调用上就可以解释得通。因为 runtime 都停止工作了，timer 自然就没法“到期”了。

接着，使用 Go 1.14 去编译有问题的代码版本，上到 test 集群，果然问题“消失”。服务状态完全恢复正常，唯一不正常的是数据文件无法 dump 下来了，因为即使是 Go 1.14，也依然在执行无限循环，不干“正事”。

接下来的问题就是找到异常的数据了。使用上线前的版本（使用 go vendor），将 codec 替换为最新的 v1.1.8 版本，并且在 quoteStr 函数里打上了几行日志：

部署到 test 集群，问题复现：

异常数据就是：“孙���雷”：

为什么会引发死循环，在调用 utf8.DecodeRuneInString 函数后：

c == utf8.RuneError



size == 3

再看 RuneError 的定义：

const RuneError = '\uFFFD'

看一下两个版本的代码不同之处：

老版本的代码，不会进入 if 分支，而新版本的代码，由于 c==utf8.RuneError，所以先进入 if 分支，之后， size==3，不满足里层分支，直接 continue 了，因此 i 值并没有发生变化，死循环就这么发生了。

最后就是找到异常数据到底属于哪个计划。我尝试去每个集群的机器上，从数据文件里寻找“孙���雷”。但文件太大了，几十个 G， grep 搞不定，没关系，使用 dd 工具：

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

‍使用二分法找到了“孙���雷”！关于 dd+grep 的用法，总结了几点：

1. 每次从文件开头先跳过 skip*bs 大小的内容，复制 count*bs 大小的内容过来用 grep 查询。
2. 如果不设置 count，就会查找整个文件，如果查到，则会有输出；否则无。
3. 对于特别大的文件，可以先把 count 设为跳过一半文件大小的值，采用二分法查找。如果找到，则限定在了前半范围，否则在后半部分。使用类似的方法继续查找……
4. 如果找到，最后会输出 count*bs 大小的内容。

反思

1. 服务重大版本更新，至少在线下跑一周。
2. 有问题，第一时间回滚。
3. 对于工具的使用要规范。如不要随意更改 vendor 文件夹的内容而不同步更新 vendor.json 文件，反之亦然。
4. 因为 go mod 的版本选择以及不遵守开源规范的第三方库作者会让使用者不知不觉、被动地引入一些难以发现的问题。可以使用 go mod vendor 代替，如果要锁死版本的话，使用 replace。