作者:Jack47
PS：如果喜欢我写的文章，欢迎关注我的微信公众账号程序员杰克，两边的文章会同步，也可以添加我的RSS订阅源。
上周四上线新业务项目时，遇到了一系列非常诡异的问题，虽然最终得以顺利解决，但是整个过程非常曲折，暴露出的问题值得引起大家的思考，在此进行复盘，希望能够作为前车之鉴，大家从中吸取经验教训。
背景
简化的交互场景如下图，其中M是业务逻辑处理的节点，上面启动了程序m，D是存储展现数据的节点，上面启动了程序d，两个节点都是部署在不同的机器上的不同的服务。M会发送查询的请求给D，D查找到这些数据，进行简单的处理后，返回给M。
M与D的交互
本次新的业务项目，在D节点需要存储的数据中新增加了几个字段，这些数据都需要返回给M。
整个上线过程及出问题的过程如下：
功能测试通过后，进行了压力测试和稳定性测试，都没有发现问题，于是上线，预期节奏是上线实验环境,上线一个C机房，再上线另外一个机房E。上线实验环境后，以实验环境能接入的最大流量，占总流量的5%观察一天，没有出现任何问题，业务的各项指标也都正常。于是在第二天晚上上线一个机房,接流20%，第三天下午2点，这个机房流量扩大到50%，此时大部分M节点上，服务进程M的CPU占用率立马飙高，达到了80%左右！
现象
1. 一个机房M节点大部分的机器CPU飙高，达到80％
迅速将流量切走后，用gdb attach命令挂到m进程，发现都阻塞在从xdbm文件(是公司的小数据内存存储方案)获取数据的地方xdbm_fetch了。重启m进程后，现象依旧。用strace查看了一下此时M的系统调用，发现都阻塞在给一个xdbm文件用xlock(公司自己实现的锁)加锁的地方了，锁文件是“/tmp/.xlock/home/x/data/data_list.xdbm.rw”。
由于m自身只是读取xdbm数据，而数据data_list.xdbm是会有更新的，所以怀疑是线上进行xdbm文件更新时有问题，导致写锁没有释放，但是也没有直接的证据。这里分析了很长一段时间，从下午一直到晚上。即使删了这个目录下的所有锁文件，启动m后，依然会阻塞在这个地方。中间一度怀疑xdbm代码自身就有问题，尝试安装了不同版本的xlock的包，也没有解决问题。后来在不断尝试各种解决办法的时候，偶然发现进程列表里有一个xdbm_replace进程。它是用来更新整个xdbm数据内容的工具，它是需要创建文件写锁的！就是这里了，把这个进程kill掉,删除锁文件后，成功启动m！现在m虽然可以启动了，但是问题依然没有合理的解释：为什么这个锁被破坏了？
在开发同学查问题的同时，测试同学也在性能测试环境里复现问题，我们捞取了出问题那段时间附近10分钟的线上m服务的查询串，对整个系统进行了压力测试，可是没能复现问题。此时性能测试环境中的D节点是老的程序＋数据，担心是这个原因导致不能复现，于是决定对D进行升级。
接下来我们调整了思路，仔细分析了发现的一个重要线索：这个锁文件里有业务的数据！而且每台机器上的内容都不完全一样，但可以肯定都是业务数据，而且这些数据都是D返回的。
这样就可以确定是M(这点很重要，排除了其他可能！)内部写内存越界，导致xdbm锁的数据内容被破坏。既然写入的是D数据，那就肯定是处理D数据的地方写入数据越界了。于是顺滕摸瓜，找到了最终要把这些数据输出到缓冲区的地方。由于本次D返回的数据字段变多，有好几个字符串类型的数据，可能导致输出时返回结果的长度变大。在看代码时发现有个数组的长度设置的有点小，很可能导致内存越界，于是迅速修改完这里的代码，然后上测试的性能环境验证。结果发现出问题了，程序会core，有core在给string赋空值的地方，也有core在new数组的地方！此时已经是晚上10点钟了。脑袋有点大了，后来觉得不对劲，又回过头仔细看了下这些业务数据，发现一些数据是图片地址，这些地址还是原始的地址，并没有拼接域名的头部，这就推翻了之前认为是拼接返回结果时写内存越界的可能性了，那就只能是另外一个地方了：M处理D返回结果的地方。
翻看代码，D返回数据是经过snappy压缩的，M需要先把数据解压缩后，再进行解析，解压缩使用的缓冲区长度为1M。接着发现这里代码逻辑有点问题，是先解压缩到缓冲区，再判断解压缩后的大小！这样就会有解压缩后缓冲区溢出的风险！修改完这里的代码，然后在性能环境上压测了1一个小时，没有出现问题！终于可以松口气了，xdbm锁被破坏的原因基本确定了，是因为M处理D返回结果时没有判断数据的大小，导致缓冲区溢出，正好是把存储xdbm锁信息的内存给破坏掉了。
此时已经是晚上2点多钟了，进行了M的上线。此时正在全链路压测，D上出现了一些ERROR日志：解析M发给D的数据时，D内部的一个缓冲区长度太小了，不能处理。看了一下代码，如果请求DN的Query中key的个数增多，超过正常的最大值200条，会有点问题，于是对其进行合理扩大。已经晚上4点了，太困了，准备睡一觉，上午来了回归测试完，上线D，修复这个问题。
2. B类请求出现问题，有大量的空结果
上午12点钟，将B类请求流量，接入到了C机房，以前一直是在还没有上线新功能的E机房。此时陆续就有客户反馈B功能不可用。拿出B类的请求串来看，发现M最终返回的数据集合是空的：
- 有一些请求串，M解析不了D返回的结果，说明D返回数据有问题
- 有一些请求串，D返回的数据集合为空
上D机器上去看系统运行日志，发现有很多ERROR日志：输出新增的imgUrl数据字段到缓冲区时，缓冲区大小不够了，因为这个字段的长度达到了几十K！正常最多也就百来字节，怎么会有这么大？
3. 有客户反馈扣费达到了1000元
祸不单行，在定位D原因时，传来了有些客户扣费达到1000元的消息。大周五的，咋出了这么多问题？反作弊同学反馈有些数据的点击串数据不正确，会触发保护策略，让实时反作弊系统发给结算的扣费价格变成1000元，此时客户的实时报表里，就看到点击扣费变成1000元了！拿到了这些有问题的PV日志，发现这些流量是从试验田出来的，于是赶紧切掉试验田的流量，问题消失，但此时已经影响到了上百个客户。此时试验田的M版本是没有修复问题1的老版本，在处理D返回结果时会有问题。所以问题肯定就是出在这里了，D返回结果变大，超过M的缓冲区大小，就会导致写内存越界，最终导致M中拼接的点击串有问题。此时是多么的希望程序能够直接core掉啊，core了至少能够有现场，而不是产生错误的数据，进而造成经济损失。
问题1和问题3同样都是缓冲区溢出的问题，现象却不一样。
继续排查问题2，D在B类请求下有问题，于是精力集中在D上。上文中提到过，D这里的ERROR日志里，都是在输出imgUrl字段的时候出错的。这里的逻辑是从数据里取出图片地址。B类请求的特点是请求的key很多，达到200个，是不是这两百个key里，有些key的数据很大？而我们处理每个key的数据时，缓冲区只有1K大小，很有可能是这里了。本次上线中，构建D的全量数据的过程也有重大调整，不能排除全量数据有问题的可能。每次B的流量来，都可以复现这个问题，于是直接到机器上去用gdb调试，在最终序列化这个字段的地方加断点，看数据到底长什么样子？
本来以为很快就能定位，结果半路又杀出个程咬金来：输出这个字段的地方，使用的是用宏定义的函数，函数内部用局部变量来获取imgUrl字段，然后输出到缓存里。导致gdb运行到这里，一次就过去了，啥都看不到。而且imgUrl的迭代器，也是用宏来写的，gdb里虽然能拿到指针，但看不到里面数据长啥样子。
在我这边确认具体原因的同时，测试修改了压力测试的Query，把里面跟key个数相关的参数都调整了一下，然后开始压力测试。发现问题可以复现了，太好了！我把D上扩大数据处理缓冲区的版本先交给了测试，进行压力测试验证，看看问题是否修复。但很快测试就发现问题依旧。此时已经到了晚上6点了，问题还是没有解决，系统工程师想要回滚我们的上线，但回滚代价很大，我们已经上了C机房了，就差E机房，如果回滚，将直接导致依赖我们上线的其他团队的本期项目也会延期发布。如果回滚，局面会非常被动。
一定要把这个bug揪出来！直接调试不行，那就看代码吧，肯定是这次改动的代码引入的，跟其他同事把这几段处理代码过了好几边，都没有发现问题。此时已经是晚上10点了，前天晚上熬夜，今天又连续很长时间查问题之后，大家的脑袋都有点僵了，此时又陷入了僵局。我去厕所洗了把脸，回来后跟另外一个同事讲了一下这里的业务逻辑。此时他提出了一个思路：既然肯定是这里的问题，那就把想要的信息都打印到日志里！Bingo，我咋没早想到这一点呢。于是上去加日志，发现DEBUG级别的日志里，基本信息都有了，于是直接开DEBUG日志。刷了一个请求，看了一下DEBUG日志，真相就大白了，在查询的key很多的情况下，候选的数据量达到了六百多个。刚刚看了很多遍imgUrl处理的地方，那里对处理的数据个数的限制是500个，那肯定就是处理时越界了！这样imgUrl字段的字符串结束符'\0'被破坏，导致这个字段超长。扩大了这里的缓冲区大小，同时加上长度的保护和错误日志来修复。后续进行压测，确定问题已经解决了。
这个bug，其实跟去年的Open SSL心脏出血，是很类似的，都是对长度没有加以判断，导致写缓冲区出现问题。
经验教训
- 如果有core产生，需要注意看core的地方，如果发现指针所指的这片内存不能访问，那十有八九被写坏了。既然被写坏了，就可以通过分析写到这里的数据的特点，来找到写入这些数据，也就是发生缓冲区溢出的地方了。如果是这种查询类服务，本次查询的请求串非常重要，出core时可以看看到底是什么样的请求串，分析一下请求串的特点。
- 程序中同一个常量的定义，一定要用同一份，坚决不要散落在各个地方，不要在每个cpp中定义一份
- 不要有思维定势，认为在线上运行了很久的代码就一定不会出问题
- 对ERROR日志要足够重视，一查到底，否则后续很可能出问题，等到出问题再查，损失就大了，而且投入的人力成本会更高
- 考虑搞一些
gdb的脚本，用来打印程序里关键的数据结构，比如M中的数据集合，通过这些关键数据来分析core的问题。目前M里的数据结构层级太深，用gdb打印内容非常不方便 - 尽量避免使用宏，如果非用不可，编译的时候，要把调试宏的选项打开：
-gdwardf-2和-g3 - 如果使用固定大小的缓冲区，那么在写入数据时，一定要做数据长度和缓冲区大小的判断，否则会导致写入溢出的数据！
最后，推荐一个很好的资料给大家，苹果公司的Secure Coding Guide
如果您看了本篇博客,觉得对您有所收获，请点击右下角的“推荐”，让更多人看到！
712
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
