“”引发的线上事故_UTF_8

夜伦

背景起因是我们使用的服务框架版本比较老，GC 次数的 metrics 打点一直为 0，咨询了相关同学后，决定升级框架。升级的过程中，出现了 use of internal package xxx not allowed 的报错，又咨询了一下相关同学后，尝试使用 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 命令：strace -p发现服务卡在 futex 系统调用上，这很明显是一个 timer，但是 timer 为何会卡住？正常情况下，会有各种像 write，read 的系统调用，至少打日志、上报 mertrics 打点数据都会有 write 系统调用吧，哈？再执行 perf top 命令：perf top相关的只有 codec 函数，再看服务进程：perf top -r 80 -g -p看 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 版本对比从现象及源码看，大概率是在 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 函数里打上了几行日志：加上 debug 日志部署到 test 集群，问题复现：问题日志异常数据就是：“XX”：中文转 Unicode为什么会引发死循环，在调用 utf8.DecodeRuneInString 函数后：c==utf8.RuneErrorsize==3再看 RuneError 的定义：constRuneError='\uFFFD'看一下两个版本的代码不同之处：codec 版本对比老版本的代码，不会进入 if 分支，而新版本的代码，由于 c == utf8.RuneError，所以先进入 if 分支，之后，size == 3，不满足里层分支，直接 continue 了，因此 i 值并没有发生变化，死循环就这么发生了。最后就是找到异常数据到底属于哪个计划。我尝试去每个集群的机器上，从数据文件里寻找“XX”。但文件太大了，几十个 G，grep 搞不定，没关系，使用 dd 工具：ddif=model_20200423155728bs=1024skip=3600000count=1200|grep'XX'使用二分法找到了“XX”！关于 dd + grep 的用法，总结了几点：每次从文件开头先跳过 skip*bs 大小的内容，复制 count*bs 大小的内容过来用 grep 查询。如果不设置 count，就会查找整个文件，如果查到，则会有输出；否则无。对于特别大的文件，可以先把 count 设为跳过一半文件大小的值，采用二分法查找。如果找到，则限定在了前半范围，否则在后半部分。使用类似的方法继续查找……如果找到，最后会输出 count*bs 大小的内容。总结这次事故的排查过程还算顺利，根因就是异常数据触发了 Go 语言里一个非常典型的”陷阱“——Go 1.14 之前的版本无法强占正在执行无限循环的协程。模拟起来也很简单：funcmain(){varxintthreads:=runtime.GOMAXPROCS(0)fori:=0;i