查找內存錯誤

(金慶的專欄 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 間隔縮小，結果出錯概率大大增加了。
由此確認，錯誤點已找到并修正了。