查找内存错误
(金庆的专栏 2019.12)
服务器进程有个偶发的崩溃,breakpad 上传的 minidump 显示调用栈不是出错的代码点,怀疑是内存错误。
从日志分析可能触发出错的指令,然后在内网调试环境下测试,很幸运地连续有几次很容易重现了。
后来反复测试可知,发送某个特殊 GM 指令 200 次就会出现一次错误,一般会在 100 次内出现。
但是以代码反复执行千次万次都不能重现,估计与时间有关,需要手动操作延续一段时间后才会触发。
出错点多数在 `boost::property_tree::ini_parser::read_ini()` 中,如下:
```
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `./GMServer.dbg'.
Program terminated with signal 11, Segmentation fault.
#0 0x00000000010ca227 in tcmalloc::SLL_Next(void*) ()
Missing separate debuginfos, use: debuginfo-install glibc-2.17-105.el7.x86_64 libgcc-4.8.5-4.el7.x86_64 libstdc++-4.8.5-4.el7.x86_64 zlib-1.2.7-15.el7.x86_64
(gdb) bt
#0 0x00000000010ca227 in tcmalloc::SLL_Next(void*) ()
#1 0x00000000010ca2b8 in tcmalloc::SLL_TryPop(void**, void**) ()
#2 0x00000000010ca715 in tcmalloc::ThreadCache::FreeList::TryPop(void**) ()
#3 0x00000000011ebe6c in tc_newarray ()
#4 0x00007efddb7d4c69 in std::string::_Rep::_S_create(unsigned long, unsigned long, std::allocator<char> const&) () from /lib64/libstdc++.so.6
#5 0x0000000000a18153 in std::string::_S_construct<char*> (__beg=0x3f6c8b9 "LobbyServer]", __end=0x3f6c8c4 "]", __a=...) at /usr/include/c++/4.8.2/bits/basic_string.tcc:138
#6 0x00007efddb7d641c in std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(std::string const&, unsigned long, unsigned long) ()
from /lib64/libstdc++.so.6
#7 0x00007efddb7d6462 in std::string::substr(unsigned long, unsigned long) const () from /lib64/libstdc++.so.6
#8 0x0000000000a3c3be in boost::property_tree::ini_parser::read_ini<boost::property_tree::basic_ptree<std::string, std::string, std::less<std::string> > > (stream=..., pt=...)
at /var/tmp/src/f4f4f712-7894-4d98-83dd-b91be8e0555e/Linux-Debug/003_servers/../000_BaseLib/3RdParty/boost/include/boost/property_tree/ini_parser.hpp:111
#9 0x0000000000a3b2f0 in boost::property_tree::ini_parser::read_ini<boost::property_tree::basic_ptree<std::string, std::string, std::less<std::string> > > (
filehelp="cfg.ini", pt=..., loc=...)
at /var/tmp/src/f4f4f712-7894-4d98-83dd-b91be8e0555e/Linux-Debug/003_servers/../000_BaseLib/3RdParty/boost/include/boost/property_tree/ini_parser.hpp:169
...
#27 0x00007efddba27dc5 in start_thread () from /lib64/libpthread.so.0
#28 0x00007efddaf341cd in clone () from /lib64/libc.so.6
(gdb) q
```
但是 property_tree 是实践证明可靠的库,暂时不去怀疑它。
其他代码有 uWS 处理HTTP 请求,用 hiredis 读写 Redis。
这些库先假定是正确的,先查看自己的代码,因为相关代码较少,可以肉眼查错,可惜只查到些无关的小错误。
然后到处添加调试日志,跟踪变量的构造与析构。
因为 uWS 中用到了一个用户自定义数据,有一个 new/delete 操作,容易出内存错误,重点就是这个数据是否存在野指针。
但是看上去正常。
肉眼查代码不行,就要用工具了。
首先添加 -fstack-protector-all 编译参数,这个参数其实无论如何都应该早就加上的,用来检测函数调用时栈破坏。
同时在自定义用户数据使用和析构时检查自身数据是否有效,如某个成员变量总是设为 0x5a, 析构时才把它置为 0xcc.
崩溃依旧,但上述内存检查正常。
再使用一个 Address Sanitizer, 只需要添加编译选项 -fsanitize=address 即可。
它用来检查堆内存是否存在非法操作。
但是这个不能和 tcmalloc 共用,我需要更改现有代码,然后链接 asan 库,终于可以运行起来了。
如果存在 tcmalloc 调用,进程启动时就会崩溃。
效果很好,准确报告 "double-free" 错误:
```
[jinqing@host-192-168-21-31 bin]$ gdb GMServer.dbg
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-80.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /home/jinqing/valkyrie/Runtime_ZT_QA/bin/GMServer.dbg...done.
(gdb) r
Starting program: /home/jinqing/valkyrie/Runtime_ZT_QA/bin/GMServer.dbg
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
iLogLevel:1
[New Thread 0x7ffff3724700 (LWP 1010)]
[New Thread 0x7ffff2c1d700 (LWP 1011)]
[New Thread 0x7ffff2116700 (LWP 1012)]
[New Thread 0x7ffff160f700 (LWP 1013)]
[New Thread 0x7ffff0b08700 (LWP 1014)]
=================================================================
==1005== ERROR: AddressSanitizer: attempting double-free on 0x6004000270d0:
#0 0x7ffff4e60dd9 (/usr/lib64/libasan.so.0.0.0+0x15dd9)
#1 0x1570e8d (/home/jinqing/valkyrie/Runtime_ZT_QA/bin/GMServer.dbg+0x1570e8 d)
0x6004000270d0 is located 0 bytes inside of 5-byte region [0x6004000270d0,0x6004 000270d5)
freed by thread T0 here:
#0 0x7ffff4e60dd9 (/usr/lib64/libasan.so.0.0.0+0x15dd9)
#1 0x1570e8d (/home/jinqing/valkyrie/Runtime_ZT_QA/bin/GMServer.dbg+0x1570e8 d)
previously allocated by thread T0 here:
#0 0x7ffff4e60ef9 (/usr/lib64/libasan.so.0.0.0+0x15ef9)
#1 0x157179e (/home/jinqing/valkyrie/Runtime_ZT_QA/bin/GMServer.dbg+0x157179 e)
Thread T4 created by T0 here:
#0 0x7ffff4e55a0a (/usr/lib64/libasan.so.0.0.0+0xaa0a)
#1 0x13fc796 (/home/jinqing/valkyrie/Runtime_ZT_QA/bin/GMServer.dbg+0x13fc79 6)
==1005== ABORTING
[Thread 0x7ffff160f700 (LWP 1013) exited]
[Thread 0x7ffff2116700 (LWP 1012) exited]
[Thread 0x7ffff2c1d700 (LWP 1011) exited]
[Thread 0x7ffff3724700 (LWP 1010) exited]
[Thread 0x7ffff7fe77c0 (LWP 1005) exited]
[Inferior 1 (process 1005) exited with code 01]
Missing separate debuginfos, use: debuginfo-install glibc-2.17-105.el7.x86_64 li basan-4.8.5-39.el7.x86_64 libgcc-4.8.5-4.el7.x86_64 libstdc++-4.8.5-4.el7.x86_64 zlib-1.2.7-15.el7.x86_64
(gdb)
```
因为用了 gcc 4.8, 所以asan没有函数名输出,gcc 4.9 以上就会有函数名了。
但是不要紧,用 nm 可以搜到函数名:
```
[jinqing@host-192-168-21-31 bin]$ nm GMServer.dbg | grep 1570e
0000000001570e50 T freeReplyObject
0000000001570ef0 T redisReaderFree
[jinqing@host-192-168-21-31 bin]$ nm GMServer.dbg | grep 15717
0000000001571750 t createStringObject
[jinqing@host-192-168-21-31 bin]$ nm GMServer.dbg | grep 13fc7
00000000013fc700 t _ZN5boost6detail23set_current_thread_dataEPNS0_16thread_data_baseE
00000000013fc7d0 T _ZN5boost6thread21start_thread_noexceptERKNS_17thread_attributesE
00000000013fc750 T _ZN5boost6thread21start_thread_noexceptEv
00000000013fc740 T _ZN5boost6threadC1Ev
00000000013fc740 T _ZN5boost6threadC2Ev
[jinqing@host-192-168-21-31 bin]$ ^C
```
显示为 freeReplyObject() 调用为 "double-free".
有了这个提示,查代码就简单了。原来查 uWS 的用户数据 new/delete 是方向性错误,
Redis 也有个 delete 操作,即返回的 ReplyObject 需要调用 freeReplyObject().
直接搜索一遍就找到了那个多余的 freeReplyObject.
原来是 ReplyObject 保存为一个成员变量,每次 Redis 操作完成后需要调用 freeReplyObject() 并将该成员设为空。
同时析构函数中也会判断该成员,非空则调用 freeReplyObject().
但是有个每 60s 执行一次的 Ping 操作,调用了 freeReplyObject(), 但是没有置空。
同时 GM 指令也触发了一次 Redis 对象重置,再次调用了 freeReplyObject()。
正确的做法是不用成员变量,每次都用临时变量就行了,但是用成员变量可以少写一行声明,写代码较方便。
为了少改代码,仍然保持为成员变量,仅把缺的置空补上了。
同时析构中的 freeReplyObject() 是没必要的,改成断言成员为空。
添了一行代码,然后测试,发现错误不出现了。如果不加这行置空,将 Ping 间隔缩小,结果出错概率大大增加了。
由此确认,错误点已找到并修正了。