最近遇到一个依赖升级+数据异常导致的上线事故，学习了很多。本文对其进行归纳总结。后台原因是我们使用的服务框架版本比较老，GC次数指标一直为0，咨询了相关同学后决定升级框架。升级过程中出现useofinternalpackagexxxnotallowed的错误。咨询过相关同学后，尝试使用gomod来解决。从govendor到gomod的升级过程也不是很顺利，这里就不展示了，最后还是升级成功了。伴随升级的还有Go版本，从1.11到1.13。周四上线后，一切似乎都很好：内存使用，GC消耗的CPU都得到了优化，GC次数的监控也可以了。因为涉及公司内部资料，就不放图了。我平安度过了周五和周六，但周日出了点问题。中午12:00左右到次日凌晨12:00，群里的同学们陆续下班。可怜我们来之不易的星期天！现象周日11点45分左右，端口调用失败率告警，同时业务方调用接口报错。同志们，关键时刻，一个完美的报警器，可以为事故的处理和恢复争取时间！通过案例排查，发现服务于shard3集群的机器报i/o超时错误。该服务共有4个shard集群（根据idhash到对应的shard），其他3个集群完全正常。然后发现shard3集群的机器内存正常，端口还在，但是in/out流量都降到了几十KB/s，日志也没有发现异常。重启shard3集群的服务，重启后的服务恢复正常，访问调试端口也正常。然而十多分钟后，恢复后的服务又不正常了：进/出流量再次下降到几十KB/s，访问调试口也没有任何反应，我开始慌了。如果启动有问题，第一时间回滚！稳定性最重要的事情之一是：如果有问题，先回滚。先止损，将事故的影响降到最低，事后追根究底，总结复盘。所以我开始回滚，重置为周四启动前的提交，重新打包，并启动shard3集群。之后，外部接口完全恢复，操作回滚到其他集群。服务启动前需要加载几十G的数据，启动过程长达10+分钟。我申请了一台在线问题机器的root权限，执行strace-p命令：发现服务卡在了futex系统调用上，明明是定时器，但是为什么定时器卡住了呢？一般情况下，都会有write、read等各种系统调用。至少会有写系统调用来记录和报告度量数据，对吧？再次执行perftop命令：只有codec函数相关，再看服务过程：看perf输出结果，都关注第三方库codec，主要两个函数codec.quoteStr和utf8.DecodeRuneInString。我们使用codec的地方就是在程序启动的时候加载数据文件和定时转储文件到本地。既然程序启动了，那只能是转储文件的问题了。查看相关日志，确实有启动转储文件的日志记录，但是一直没有转储成功的记录。在post-mortem阶段，尝试在测试集群上重现故障，因为只有一个分片有问题，说明故障与具体数据有关，问题出在散列到分片3的数据上。和因为测试集群没有分片，所以强行伪装成shard3集群（改代码&&改环境变量），但是没有重现。据推测，该计划可能会下线。周二在测试集群上模拟sharding1时终于重现了线上故障。对比codec版本问题，确实有问题：周四上线前，vendor.json里的版本是v1.1.7，上线后升级到v1.1.8，看来问题找到了！修改codec版本，重新编译部署，问题依旧！这时候群里其他同学反映2018年也出现了编解码问题，当时也出现了数据异常，导致重启时无法加载文件。于是直接对比了周四上线前vendor文件夹下的codec.quoteStr函数代码和codec的v1.1.7代码，不一样！vendor.json中的版本不能正确反映供应商中的实际编解码器版本！！！进一步查看提交记录，发现2017年11月有一次提交，修改了vendor文件夹中的代码，但此时vendor.json中没有codec记录。在2019年11月的一次投稿中，只在vendor.json中增加了一条codec记录，vendor文件夹中的代码保持不变：{"checksumSHA1":"wfboMqCTVImg0gW31jvyvCymJPE=","path":"github.com/ugorji/go/codec","re??vision":"e118e2d506a6b252f6b85f2e2f2ac1bfed82f1b8","re??visionTime":"2019-07-23T09:17:30Z","tree":true}仔细对比代码，主要区别在这里：从根据现象还有源码，codec.quoteStr中很大概率存在死循环！在Go1.14之前，没有任何函数调用是不可能抢占一个正在执行死循环的goroutine的，所以一旦发生死循环，在即将进行GC的时候，其他的goroutine都会停止，都在等待无限循环goroutine停止，不幸的是，由于for{}循环中没有函数调用，抢占标记无法插入抢占。结果就出现了这样的场景：只有dump数据文件一个goroutine在工作，干的是死循环，服务整体对外性能好像“崩溃”了。而这个goroutine是由定时器触发的，所以我们一开始看到的stuckonafutexcall就可以解释了。因为运行时已经停止工作，定时器自然不能“过期”。然后，使用Go1.14编译出问题代码版本，进入测试集群，问题“消失”。服务状态已完全恢复正常。唯一不正常的是数据文件无法dump，因为即使是Go1.14，依然在死循环，不做“正事”。下一个问题是找到异常数据。使用上线前的版本（使用govendor），将codec替换为最新的v1.1.8版本，在quoteStr函数中放入几行日志：部署到测试集群，问题重现：异常数据为：《太阳“雷雷”：为什么会造成死循环？调用utf8.DecodeRuneInString函数后：c==utf8.RuneErrorsize==3再看RuneError的定义：constRuneError='\\uFFFD'看两个版本代码的区别：老版本的代码不会进入if分支，而新版本的代码，因为c==utf8.RuneError，所以先进入if分支，然后，size==3，不满足内分支，直接继续，所以i的值没变，死循环刚好发生。最后就是找异常数据是属于哪个plan的，我试了找从各个集群的机器上的数据文件中“孙雷”。但是文件太大了，几十G，grep搞不定，d没关系，用dd工具：ddif=model_20200423155728bs=1024skip=3600000count=1200|grep'Sun??雷'?用二分法找“太阳”雷！关于dd+grep的用法，我总结了几点：每次从文件开头跳过skip*bssize的内容，复制count*bssize的内容用grep查询。如果不设置count，则搜索整个文件，找到则有输出；否则，什么都没有。对于特别大的文件，可以先将count设置为跳过文件大小一半的值，采用二分查找的方式。如果找到，则限制在范围的前半部分，否则在范围的后半部分。用类似的方法继续查找...如果找到，最后会输出count*bssize的内容。Reflection服务于主要版本更新并离线运行至少一周。如果有问题，尽快回滚。规范工具的使用。例如，不要在未同步更新vendor.json文件的情况下更改vendor文件夹的内容，反之亦然。因为gomod的版本选择和不符合开源规范的第三方库作者会让用户不自觉地被动引入一些难以发现的问题。你可以改用gomodvendor，如果你想锁定版本，使用replace。
