云风的 BLOG: 一次内存越界的 bug

最近我们的手游上线，一开始稳定的跑了好几天，最近两天开始平均 30 小时崩溃一次。这个周末我们一直在查这个 bug 。

第一次崩溃发生在周六凌晨 1:00 左右，没有收集到 core 文件，只有事故现场的寄存器的值(通过查看 kern.log 和 dmesg )。通过 EIP 寄存器最终定位到是在内存分配器中出的错。

我们用的 jemalloc ，崩溃发生在一段红黑树插入节点的代码中。这里的 pathp 指针变成了 NULL 。

昨天在岩馆攀岩的时候，我脑子里一直在转这段代码，想为什么这个局部变量会变成 NULL 。反复推测的结果是 path 这个局部数组越界了，导致把 pathp 改写。

这段代码是用来展开一颗红黑树的，如果树的数据结构正常，128 一定够用，不会越界。比较可能的解释是插入了相同的节点，导致树结构绕接。虽然 jemalloc 在这里加了 assert ，但似乎在最终的程序中没有生效。

我推测是在内存释放的时候调整红黑树的，虽然我们的崩溃没有产生 core 文件，但从网上搜索到另一条类似的信息可以佐证我的推测：这条 bug report 报告了一个类似的崩溃。从调用栈来看，的确是在内存释放时发生的。

我的第一次推测是我们有些代码对指针做了 double free ，导致了红黑树节点绕接，间接导致后续的 free 操作不正常，让树展开代码越界。如果这个推测成立，那么即使我们拿到完整的 core 文件，对我们 debug 也没有什么帮助。因为数据结构是事先被破坏掉，才会导致后面的操作出错。

今天上午 10 点左右发生了第二次崩溃。这次收集到了 core 文件。

这次的错误点和上一次相同，但现象有所不同，并没有访问 NULL 地址。double free 的猜测应该是不成立的。但和我的推测相同，core 文件中可以看到调用栈的确是从 free 过来的，其它信息则没有什么用。数据结构早就被破坏了，事故现场是一次正常的 lua state 关闭操作（引发大量内存回收）。

但可以肯定的是这起 bug 最近连发两次，每次间隔都是 30 小时左右，一定是最近代码的修改造成的。我们翻看了最近的修改。对 C 代码的修改只有一两个位置，之前反复看了好几次都没有发现问题。不得以再看一次。

最后终于发现了问题，是一个简单的内存越界造成的：

我们上周发现有玩家客户端发过来的数据包解包失败，但不知道原因，所以增加了一个函数把错误的数据包以 16 进制输出到 log 的函数。晓靖同学是这样写的：

  char *buffer = calloc(sz*2+1, sizeof(char));

先分配一块内存，长度是要 dump 的数据长度两倍加一。然后循环

  sprintf(buffer+i*2, "%02x", data[i]);

这就是我们看了几次没留意的 bug 所在：data 是 const char 类型，有符号的。当 data[i] 是一个负数时， %02x 不一定只输出 3 个字节(别忘记字符串结尾的 \0)。buffer 这块内存就被写越界了。

Comments

sprintf_s

Posted by: Anonymous | (38) December 29, 2014 01:14 PM

我都是用snprintf

Posted by: cc | (37) July 15, 2014 02:42 PM

没看出来和\0有什么关系。倒是觉得data[sz-1]为负数时，sprintf会写buffer+(sz-1)*2+3 = buffer+2*sz+1才造成的越界。

Posted by: 十年草木 | (36) April 2, 2014 09:35 PM

应该使用SNPRINTF，STRNCPY这类的函数会稳妥些吧，强烈建议博主能分享下debug的知识，或者推荐相关的blog。

Posted by: simon | (35) March 4, 2014 01:17 PM

正好在用这个，忽然想起来这篇博客，真的是用起来才知道是要这样

Posted by: ChinaHome | (34) February 20, 2014 06:21 PM

难道不是%02hhx么？

Posted by: asdfg | (33) February 20, 2014 04:20 PM

测试时没有越界不代表测试数据没有负数，而很可能测试数据最后几位不是负数而已，要越界只有碰巧最后几位字符是负数才行，前面的字符有负数只是得不到正确的结果而已。

Posted by: 观雨 | (32) February 8, 2014 02:41 PM

printf 中的 field length 经常被误用，应该重写一个用来表示最大长度的directive，这样会让错误检查所消耗的时间减少。

Posted by: marmot | (31) February 7, 2014 10:26 PM

我们会统一规定所有字节流基本类型为 uint8_t, 这样遇到类似这种 default argument promotions / integer promotions时也能够稍微简单一些。

Posted by: marmot | (30) February 5, 2014 09:30 PM

生成字符串转换的坑实在太多。

Posted by: anthony | (29) January 22, 2014 12:24 PM

string +=的效率是ostringstream<的2倍，ostringstream<<的效率是snsprintf的二倍。抛弃c选择c++吧！

Posted by: wellmv | (28) January 21, 2014 11:35 PM

这里用 sprintf 感觉效率不高，还不如直接四位一组直接算呢。

Posted by: cyberscorpio | (27) January 14, 2014 01:49 AM

一开始怀疑jemalloc里出了问题，后来证实还是自己的代码出了问题。

Posted by: Liigo | (26) January 11, 2014 06:09 PM

这里要注意下，以免自己也被坑。

Posted by: lite3 | (25) January 10, 2014 09:06 AM

vc下也会这样。 char buf[10] = {0}; sprintf(buf,"%02x",-3); printf("%s\r\n",buf); 输出：fffffffd char buf[10] = {0}; sprintf(buf,"%02x",(unsigned char)-3); printf("%s\r\n",buf); 输出：fd

Posted by: yanbin | (24) January 9, 2014 08:17 PM

这种打印16进制，我一般自己写个宏来转换

Posted by: starshine | (23) January 8, 2014 11:36 AM

@chengli 刚刚翻了下the c programming language 确实除了%d %i和实数，其他格式化输出都是unsigned

Posted by: Julius | (22) January 8, 2014 09:53 AM

@chengli 嗯，奇怪的是我实测居然没有负号...所以我怀疑是不是我的g++抽搐了

Posted by: Julius | (21) January 8, 2014 09:42 AM

晓靖同学跪键盘去。。。

Posted by: Smite | (20) January 8, 2014 12:05 AM

why not snprintf?

Posted by: jacky | (19) January 7, 2014 11:01 PM

alloc分配的堆上面的内存 pathp 指针变成了 NULL 局部变量是在栈上的。堆区踩内存踩到了栈上么？不懂

Posted by: yang | (18) January 7, 2014 11:44 AM

@ Julius 应该是8个字符，跟负号，'\0'什么的没关系。‘%02d’只是说宽度最小为2

Posted by: chengli | (17) January 7, 2014 10:51 AM

确实很隐晦的bug "%02x"在负数char时，输出8个字符，而不是带负号的3个字符不知是否是我用的g++缘故

Posted by: Julius | (16) January 7, 2014 10:36 AM

mark下，这个bug确实很容易蒙人。

Posted by: hemaolong | (15) January 7, 2014 09:39 AM

@hedengcheng kern.log 和 dmesg 里有 log

Posted by: Cloud | (14) January 7, 2014 09:37 AM

哈哈，点名批评的意思啊，mark警示下

Posted by: johnzz | (13) January 7, 2014 09:10 AM

引用：我们上周发现有玩家客户端发过来的数据包解包失败，但不知道原因我们前段时间也遇到了这个问题，后面根据大量的数据分析，揣测应该是有用户在网络层拦截了CS的包，串改了data 导致和协议结构造成差异无法解析对于这样的情况，我们在data第一字段增加包验证信息可以fix 但是我们最终采取的是验证客户端的包实际长度和拼包时长度进行验证只能保证部分被篡改的可能毕竟他将流中的0修改为1 是可以解析过的，错误让上层逻辑抛出。

Posted by: injur | (12) January 7, 2014 08:56 AM

我们上周发现有玩家客户端发过来的数据包解包失败，但不知道原因我们前段时间也遇到了这个问题，后面根据大量的数据分析，揣测应该是有用户在网络层拦截了CS的包，串改了date 导致和协议结构造成差异无法解析对于这样的情况，我们在data第一字段增加包验证信息可以fix

Posted by: injur | (11) January 7, 2014 08:51 AM

也就是最后一个字符是负数的时候就越界了超过两个字符把尾部得0覆盖掉了所以问题就来了

Posted by: 小邓 | (10) January 7, 2014 01:04 AM

在java里所有数值类型都是有符号的(char除外), 所以这坑已经铭记于心, 一眼就看出这个问题了...不过java是肯定无法越界的(Unsafe类除外),查bug比C/C++方便太多

Posted by: dwing | (9) January 6, 2014 10:20 PM

sprintf(buffer+i*2, "%02x", (unsigned char)data[i]);

Posted by: xx | (8) January 6, 2014 09:01 PM

@Fenng 你不算结束的 \0 么？

Posted by: Cloud | (7) January 6, 2014 08:53 PM

第一次崩溃发生在周六凌晨 1:00 左右，没有收集到 core 文件，只有事故现场的寄存器的值。通过 EIP 寄存器最终定位到是在内存分配器中出的错。我对这个是怎么做的，比较好奇，云风能不能分享下？程序都崩溃了，如何查询寄存器的值？如何根据寄存器的值定位程序出错的调用栈？