net_tests/caddrdb_read_corrupted failure: stack overflow #16575

Tests are failing on Head of master.

I'm building on Windows 10 with MS Visual Studio 2017.

The command line I'm using is:

test_bitcoin.exe -r confirm

The tests are failing just in x64 Debug mode. The full output is:

Edit: x86 Debug mode is also failing

C:\_D\Repos\bitcoin\build_msvc\x64\Debug>test_bitcoin.exe -r confirm
Running 356 test cases...
unknown location(0): fatal error: in "net_tests/caddrdb_read_corrupted": stack overflow
c:\_d\repos\bitcoin\src\test\net_tests.cpp(165): last checkpoint

*** 1 failure is detected in the test module "Bitcoin Core Test Suite"
Detected memory leaks!
Dumping objects ->
{13091797} normal block at 0x000002D5726909A0, 16 bytes long.
 Data: <XW              > 58 57 A0 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091796} normal block at 0x000002D5726447F0, 112 bytes long.
 Data: <ERROR: Deseriali> 45 52 52 4F 52 3A 20 44 65 73 65 72 69 61 6C 69
{13091795} normal block at 0x000002D5726913F0, 16 bytes long.
 Data: < [              > C8 5B A0 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091793} normal block at 0x000002D572643CF0, 112 bytes long.
 Data: <ERROR: Deseriali> 45 52 52 4F 52 3A 20 44 65 73 65 72 69 61 6C 69
{13091792} normal block at 0x000002D5726915D0, 16 bytes long.
 Data: <(^              > 28 5E A0 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091784} normal block at 0x000002D572643770, 112 bytes long.
 Data: <DeserializeDB: D> 44 65 73 65 72 69 61 6C 69 7A 65 44 42 3A 20 44
{13091783} normal block at 0x000002D572691260, 16 bytes long.
 Data: < a              > E8 61 A0 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091768} normal block at 0x000002D56C588220, 144 bytes long.
 Data: <p Xl      Xl    > 70 96 58 6C D5 02 00 00 F0 8F 58 6C D5 02 00 00
{13091767} normal block at 0x000002D56C6E1400, 4 bytes long.
 Data: <    > 00 00 00 00
{13091766} normal block at 0x000002D57122C910, 56 bytes long.
 Data: <  "q      "q    > 10 CF 22 71 D5 02 00 00 10 CF 22 71 D5 02 00 00
{13091765} normal block at 0x000002D56C588FF0, 144 bytes long.
 Data: <p Xl    p Xl    > 70 96 58 6C D5 02 00 00 70 96 58 6C D5 02 00 00
{13091764} normal block at 0x000002D572691530, 16 bytes long.
 Data: <                > B8 AD AA E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091763} normal block at 0x000002D56BF7BC60, 192 bytes long.
 Data: <C : \ U s e r s > 43 00 3A 00 5C 00 55 00 73 00 65 00 72 00 73 00
{13091762} normal block at 0x000002D572691670, 16 bytes long.
 Data: <                > D8 AE AF E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091753} normal block at 0x000002D572691490, 16 bytes long.
 Data: <                > E8 AD AF E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091752} normal block at 0x000002D577E83040, 32 bytes long.
 Data: <@0 w [@0](/bitcoin-bitcoin/contributor/0/) w    > 40 30 E8 77 D5 02 00 00 40 30 E8 77 D5 02 00 00
{13091750} normal block at 0x000002D572690DB0, 16 bytes long.
 Data: <                > A0 AD AA E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091749} normal block at 0x000002D57122CF10, 56 bytes long.
 Data: <  "q      "q    > 10 C9 22 71 D5 02 00 00 10 C9 22 71 D5 02 00 00
{13091748} normal block at 0x000002D572690630, 16 bytes long.
 Data: <                > 88 AD AA E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091747} normal block at 0x000002D56C589670, 144 bytes long.
 Data: <  Xl      Xl    > F0 8F 58 6C D5 02 00 00 F0 8F 58 6C D5 02 00 00
{13091746} normal block at 0x000002D5726441C0, 112 bytes long.
 Data: <                > F9 BE B4 D9 01 20 00 00 00 00 00 00 00 00 00 00
{13091745} normal block at 0x000002D572691350, 16 bytes long.
 Data: <                > D8 AC AA E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091711} normal block at 0x000002D56C589C20, 144 bytes long.
 Data: <  Xl      Xl    > 90 91 58 6C D5 02 00 00 80 80 58 6C D5 02 00 00
{13091710} normal block at 0x000002D56C6E1C00, 4 bytes long.
 Data: <    > 00 00 00 00
{13091709} normal block at 0x000002D57122D210, 56 bytes long.
 Data: <  "q      "q    > 90 E0 22 71 D5 02 00 00 90 E0 22 71 D5 02 00 00
{13091708} normal block at 0x000002D56C588080, 144 bytes long.
 Data: <  Xl      Xl    > 90 91 58 6C D5 02 00 00 90 91 58 6C D5 02 00 00
{13091707} normal block at 0x000002D572691210, 16 bytes long.
 Data: <                > 98 AB A5 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091705} normal block at 0x000002D572691030, 16 bytes long.
 Data: <                > C8 AB AA E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091704} normal block at 0x000002D577E82A40, 32 bytes long.
 Data: <@* w    @* w    > 40 2A E8 77 D5 02 00 00 40 2A E8 77 D5 02 00 00
{13091702} normal block at 0x000002D572690FE0, 16 bytes long.
 Data: <                > 80 AB A5 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091701} normal block at 0x000002D57122E090, 56 bytes long.
 Data: <  "q      "q    > 10 D2 22 71 D5 02 00 00 10 D2 22 71 D5 02 00 00
{13091700} normal block at 0x000002D5726918A0, 16 bytes long.
 Data: <h               > 68 AB A5 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091699} normal block at 0x000002D56C589190, 144 bytes long.
 Data: <  Xl      Xl    > 80 80 58 6C D5 02 00 00 80 80 58 6C D5 02 00 00
{13091698} normal block at 0x000002D572643A30, 112 bytes long.
 Data: <                > F9 BE B4 D9 01 20 00 00 00 00 00 00 00 00 00 00
{13091697} normal block at 0x000002D572690F90, 16 bytes long.
 Data: <                > 98 AA A5 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091672} normal block at 0x000002D572690BD0, 16 bytes long.
 Data: <                > 80 A9 A0 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091671} normal block at 0x000002D572690EF0, 16 bytes long.
 Data: <                > B0 A9 A5 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091670} normal block at 0x000002D577E82500, 32 bytes long.
 Data: < % w     % w    > 00 25 E8 77 D5 02 00 00 00 25 E8 77 D5 02 00 00
{13091668} normal block at 0x000002D5726916C0, 16 bytes long.
 Data: <h               > 68 A9 A0 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091667} normal block at 0x000002D57122CB10, 56 bytes long.
 Data: <  "q      "q    > 10 CB 22 71 D5 02 00 00 10 CB 22 71 D5 02 00 00
{13091666} normal block at 0x000002D572690900, 16 bytes long.
 Data: <P               > 50 A9 A0 E6 EC 00 00 00 00 00 00 00 00 00 00 00
{13091665} normal block at 0x000002D56C589F60, 144 bytes long.
 Data: <` Xl    ` Xl    > 60 9F 58 6C D5 02 00 00 60 9F 58 6C D5 02 00 00
{13091490} normal block at 0x000002D56C61AED0, 65536 bytes long.
 Data: < K  H    l   { V> B5 4B 04 BA 48 E5 CE FB D0 6C DE 08 1F 7B 81 56
{13091489} normal block at 0x000002D56C672970, 208 bytes long.
 Data: <          al    > 00 00 00 00 00 00 00 00 D0 AE 61 6C D5 02 00 00
{13091197} normal block at 0x000002D56BF78D60, 192 bytes long.
 Data: <C : \ U s e r s > 43 00 3A 00 5C 00 55 00 73 00 65 00 72 00 73 00
{13091196} normal block at 0x000002D5726912B0, 16 bytes long.
 Data: <@= k            > 40 3D F7 6B D5 02 00 00 00 00 00 00 00 00 00 00
{13090848} normal block at 0x000002D56BF79660, 190 bytes long.
 Data: <C : \ U s e r s > 43 00 3A 00 5C 00 55 00 73 00 65 00 72 00 73 00
{13090791} normal block at 0x000002D572690D10, 16 bytes long.
 Data: <                > 00 BF AF E6 EC 00 00 00 00 00 00 00 00 00 00 00
{2211747} normal block at 0x000002D56C5D7570, 8 bytes long.
 Data: <        > 00 EC 02 E1 F6 7F 00 00
{2211746} normal block at 0x000002D56C5D7C00, 8 bytes long.
 Data: < D      > A8 44 03 E1 F6 7F 00 00
{31155} normal block at 0x000002D56C5CFAA0, 16 bytes long.
 Data: < = k            > 18 3D F7 6B D5 02 00 00 00 00 00 00 00 00 00 00
{31154} normal block at 0x000002D56C611820, 56 bytes long.
 Data: <  al      al    > 20 18 61 6C D5 02 00 00 20 18 61 6C D5 02 00 00
{31153} normal block at 0x000002D56BF73CC0, 176 bytes long.
 Data: <         9      > 02 00 00 00 00 00 00 00 90 39 04 E1 F6 7F 00 00
{7515} normal block at 0x000002D56C0C5070, 1048576 bytes long.
 Data: <    [  Y ( -    > 98 17 F8 16 5B 81 F2 59 D9 28 CE 2D DB FC 9B 02
{7514} normal block at 0x000002D56A3F4A90, 208 bytes long.
 Data: <pP l            > 70 50 0C 6C D5 02 00 00 00 00 00 00 00 00 00 00
Object dump complete.

I can confirm the same thing. Also with Windows 10 and VS 2017. In my case x64.

c:\Dev\github\sipsorcery_bitcoin\src>test_bitcoin.exe
Running 358 test cases...
unknown location(0): fatal error: in "net_tests/caddrdb_read_corrupted": stack overflow
c:\dev\github\sipsorcery_bitcoin\src\test\net_tests.cpp(165): last checkpoint

*** 1 failure is detected in the test module "Bitcoin Core Test Suite"
Detected memory leaks!
Dumping objects ->
{13151881} normal block at 0x000001CF3C63FA60, 16 bytes long.
 Data: < \              > A8 5C 05 97 C3 00 00 00 00 00 00 00 00 00 00 00
....

Will do some digging.

Stack trace below for the failing net_tests/caddrdb_read_corrupted unit test.

The strange thing is the tests are passing correctly in the appveyor msbuild job (update: the appveyor job does a release build so that could be the reason).

src\test_bitcoin.exe -k stdout -e stdout 2> NUL
Running 358 test cases...
*** No errors detected

I've looked over commit history but didn't spot a smoking gun. Will step back a few commits and to try and track down where the test starts failing.

 	test_bitcoin.exe!common_vsprintf<__crt_stdio_output::format_validation_base,char>(const unsigned __int64 options, char * const buffer, const unsigned __int64 buffer_count, const char * const format, __crt_locale_pointers * const locale, char * const arglist) Line 141	C++
 	test_bitcoin.exe!common_vsprintf_s<char>(const unsigned __int64 options, char * const buffer, const unsigned __int64 buffer_count, const char * const format, __crt_locale_pointers * const locale, char * const arglist) Line 268	C++
 	test_bitcoin.exe!__stdio_common_vsprintf_s(unsigned __int64 options, char * buffer, unsigned __int64 buffer_count, const char * format, __crt_locale_pointers * locale, char * arglist) Line 297	C++
 	[External Code]	
 	test_bitcoin.exe!tinyformat::formatValue<int>(std::basic_ostream<char,std::char_traits<char> > & out, const char * __formal, const char * fmtEnd, int ntrunc, const int & value) Line 346	C++
 	test_bitcoin.exe!tinyformat::detail::FormatArg::formatImpl<int>(std::basic_ostream<char,std::char_traits<char> > & out, const char * fmtBegin, const char * fmtEnd, int ntrunc, const void * value) Line 532	C++
 	test_bitcoin.exe!tinyformat::detail::FormatArg::format(std::basic_ostream<char,std::char_traits<char> > & out, const char * fmtBegin, const char * fmtEnd, int ntrunc) Line 517	C++
 	test_bitcoin.exe!tinyformat::detail::formatImpl(std::basic_ostream<char,std::char_traits<char> > & out, const char * fmt, const tinyformat::detail::FormatArg * formatters, int numFormatters) Line 816	C++
 	test_bitcoin.exe!tinyformat::vformat(std::basic_ostream<char,std::char_traits<char> > & out, const char * fmt, const tinyformat::FormatList & list) Line 960	C++
 	test_bitcoin.exe!tinyformat::format<int,int,int,int,int,int>(std::basic_ostream<char,std::char_traits<char> > & out, const char * fmt, const int & <args_0>, const int & <args_1>, const int & <args_2>, const int & <args_3>, const int & <args_4>, const int & <args_5>) Line 970	C++
 	test_bitcoin.exe!tinyformat::format<int,int,int,int,int,int>(const char * fmt, const int & <args_0>, const int & <args_1>, const int & <args_2>, const int & <args_3>, const int & <args_4>, const int & <args_5>) Line 979	C++
 	test_bitcoin.exe!FormatISO8601DateTime(__int64 nTime) Line 101	C++
 	test_bitcoin.exe!BCLog::Logger::LogTimestampStr(const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & str) Line 211	C++
 	test_bitcoin.exe!BCLog::Logger::LogPrintStr(const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & str) Line 236	C++
 	test_bitcoin.exe!LogPrintf<std::basic_string<char,std::char_traits<char>,std::allocator<char> > >(const char * fmt, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & <args_0>) Line 154	C++
 	test_bitcoin.exe!error<char [14],char const *>(const char * fmt, const char[14] & <args_0>, const char * const & <args_1>) Line 49	C++
 	test_bitcoin.exe!``anonymous namespace'::DeserializeDB<CDataStream,CAddrMan>'::`1'::catch$0() Line 100	C++
 	[External Code]	
 	test_bitcoin.exe!`anonymous namespace'::DeserializeDB<CDataStream,CAddrMan>(CDataStream & stream, CAddrMan & data, bool fCheckSum) Line 91	C++
 	test_bitcoin.exe!CAddrDB::Read(CAddrMan & addr, CDataStream & ssPeers) Line 151	C++
>	test_bitcoin.exe!net_tests::caddrdb_read_corrupted::test_method() Line 165	C++
 	test_bitcoin.exe!net_tests::caddrdb_read_corrupted_invoker() Line 138	C++
 	test_bitcoin.exe!boost::detail::function::void_function_invoker0<void (__cdecl*)(void),void>::invoke(boost::detail::function::function_buffer & function_ptr) Line 118	C++
 	test_bitcoin.exe!boost::function0<void>::operator()() Line 765	C++
 	test_bitcoin.exe!boost::detail::forward::operator()() Line 1368	C++
 	test_bitcoin.exe!boost::detail::function::function_obj_invoker0<boost::detail::forward,int>::invoke(boost::detail::function::function_buffer & function_obj_ptr) Line 138	C++
 	test_bitcoin.exe!boost::function0<int>::operator()() Line 765	C++
 	test_bitcoin.exe!boost::detail::do_invoke<boost::shared_ptr<boost::detail::translator_holder_base>,boost::function<int __cdecl(void)> >(const boost::shared_ptr<boost::detail::translator_holder_base> & tr, const boost::function<int __cdecl(void)> & F) Line 290	C++
 	test_bitcoin.exe!boost::execution_monitor::catch_signals(const boost::function<int __cdecl(void)> & F) Line 1195	C++
 	test_bitcoin.exe!boost::execution_monitor::execute(const boost::function<int __cdecl(void)> & F) Line 1277	C++
 	test_bitcoin.exe!boost::execution_monitor::vexecute(const boost::function<void __cdecl(void)> & F) Line 1377	C++
 	test_bitcoin.exe!boost::unit_test::unit_test_monitor_t::execute_and_translate(const boost::function<void __cdecl(void)> & func, unsigned long timeout_microseconds) Line 49	C++
 	test_bitcoin.exe!boost::unit_test::framework::state::execute_test_tree(unsigned long tu_id, unsigned long timeout_microseconds, const boost::unit_test::framework::state::random_generator_helper * const p_random_generator) Line 823	C++
 	test_bitcoin.exe!boost::unit_test::framework::state::execute_test_tree(unsigned long tu_id, unsigned long timeout_microseconds, const boost::unit_test::framework::state::random_generator_helper * const p_random_generator) Line 744	C++
 	test_bitcoin.exe!boost::unit_test::framework::state::execute_test_tree(unsigned long tu_id, unsigned long timeout_microseconds, const boost::unit_test::framework::state::random_generator_helper * const p_random_generator) Line 744	C++
 	test_bitcoin.exe!boost::unit_test::framework::run(unsigned long id, bool continue_test) Line 1688	C++
 	test_bitcoin.exe!boost::unit_test::unit_test_main(boost::unit_test::test_suite *(*)(int, char * *) init_func, int argc, char * * argv) Line 250	C++
 	test_bitcoin.exe!main(int argc, char * * argv) Line 305	C++
 	[External Code]	

The memory corruption is occurring in addrdb.cpp and DeserializeDB.

When the two template types are Stream = CDataStream and Data = CAddrMan the line below results in a memory violation. The CDataStream object only has 112 bytes and when the attempt is made to deserialise the CAddrMan object the stream needs a lot more than 112 bytes (there are only 108 left by then since 4 bytes are used for a file header).

 // de-serialize data
 verifier >> data;

I suspect the fact that somebody wrote this test means they believe it is a situation that can occur. In the CDataStream class the read method is checking whether the stream has enough data ~but the Unserialize methods don't seem to be? That's what's happening here. CDataStream.Unserialize is being called for CAddrMan but there are only 108 bytes available and nothing is preventing reading past the end of CDataStream's underlying vector~ update: after testing some isolated serialisation cases there are bounds checks on all the reads I came across. Instead it might be an counter gets corrupted somewhere and then tries to read too many elements. Will keep digging.

I certainly could have missed something very obvious but it does look like this is more than just an msvc issue.

Would it make sense to run appveyor in debug mode?

Running the debug version of test_bitcoin.exe takes a looong time. I'll run some tests and see what it pushed the appveyor build time out to.

I've stepped through just about every line of code in the caddrdb_read_corrupted unit test and I can't locate any likely suspects for memory leaks or corruption. In addition if I take the test logic out of the Boost test harness and run it as a console application it performs differently. It doesn't pass but the Visual Studio C Runtime Debugging library detects a memory leak in random.cpp.

I wouldn't rule out there being an issue but I tend to think it's slightly more likely it could be in the Microsoft CRT Debug libraries. The library is doing things like replacing every call to malloc, free etc. with custom debug versions and attempting to track all memory allocations. That's a very tricky thing to do and I'm reckon the "C" means it's a very old library that's perhaps not perfect with C++.

Further suspicions are aroused by getting different types of errors. The debugger initially reports a stack overflow error in a CRT library but then a memory leak in the test output. Maybe one is causing the other or the test is overwriting memory somewhere (which I don't think it is).

After 2 days I'm going to put the test failure down to a false positive by Visual Studio and the CRT Debug Library.

It doesn't pass but the Visual Studio C Runtime Debugging library detects a memory leak in random.cpp.

There is a known and desired leak in

https://github.com/bitcoin/bitcoin/blob/6dfa9efa3f558deaca0f01f673c79cce2b92a2b3/test/sanitizer_suppressions/lsan#L8-L9

Would it make sense to run appveyor in debug mode?

Two appveyor test runs of a debug build both timed out attempting to run the test_bitcoin.exe. First build took 22 minutes after which test_bitcoin.exe was executed and the job was killed after 60 minutes. Second build took 16 minutes and the job was killed after 50 minutes.

I think it will end up being counter productive to run the appveyor job with a debug configuration.

I think it will end up being counter productive to run the appveyor job with a debug configuration.

Makes sense. Thanks for looking into this!

Is this still an issue with a recent version of Bitcoin Core?