index: ThreadSanitizer: data race on vptr

fanquake commented at 2:06 pm on March 28, 2023: member

Seen with master @ 220008604f15d5078092dea28be3e3f7f11b6c8f on aarch64 (with NO_BDB=1). Follow up from #27298. See also #26188.

 02023-03-28T13:52:47.882295Z (mocktime: 2020-08-31T15:34:12Z) [test] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully
 12023-03-28T13:52:47.882390Z (mocktime: 2020-08-31T15:34:12Z) [test] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /tmp/test_common_Bitcoin Core/0959fba80d599fe246b0b5ced04b4d1ecd504db9812edbff4ada2d88c6b218ae/regtest/indexes/txindex: 0000000000000000
 22023-03-28T13:52:47.884002Z (mocktime: 2020-08-31T15:34:12Z) [txindex] [util/thread.cpp:20] [TraceThread] txindex thread start
 3test/txindex_tests.cpp(38): fatal error: in "txindex_tests/txindex_initial_sync": critical check time_start + timeout_ms > GetTimeMillis() has failed
 4LLVMSymbolizer: error reading file: No such file or directory
 5make[3]: *** [Makefile:21823: test/txindex_tests.cpp.test] Error 1
 6make[3]: Leaving directory '/home/fedora/bitcoin/ci/scratch/build/bitcoin-aarch64-unknown-linux-gnu/src'
 7make[2]: *** [Makefile:19828: check-am] Error 2
 8make[2]: Leaving directory '/home/fedora/bitcoin/ci/scratch/build/bitcoin-aarch64-unknown-linux-gnu/src'
 9make[1]: *** [Makefile:19493: check-recursive] Error 1
10make[1]: Leaving directory '/home/fedora/bitcoin/ci/scratch/build/bitcoin-aarch64-unknown-linux-gnu/src'
11make: *** [Makefile:816: check-recursive] Error 1
12==================
13WARNING: ThreadSanitizer: data race on vptr (ctor/dtor vs virtual call) (pid=24142)
14  Write of size 8 at 0xfffffee67968 by main thread:
15    [#0](/bitcoin-bitcoin/0/) BaseIndex::~BaseIndex() src/index/base.cpp:80:1 (test_bitcoin+0xc54cc8) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
16    [#1](/bitcoin-bitcoin/1/) TxIndex::~TxIndex() src/index/txindex.cpp:56:19 (test_bitcoin+0xc6daec) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
17    [#2](/bitcoin-bitcoin/2/) txindex_tests::txindex_initial_sync::test_method() src/test/txindex_tests.cpp:82:1 (test_bitcoin+0x7c281c) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
18    [#3](/bitcoin-bitcoin/3/) txindex_tests::txindex_initial_sync_invoker() src/test/txindex_tests.cpp:17:1 (test_bitcoin+0x7c0f78) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
19    [#4](/bitcoin-bitcoin/4/) boost::detail::function::void_function_invoker0<void (*)(), void>::invoke(boost::detail::function::function_buffer&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:117:11 (test_bitcoin+0x2b78e8) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
20    [#5](/bitcoin-bitcoin/5/) boost::function0<void>::operator()() const /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:763:14 (test_bitcoin+0x24f35c) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
21    [#6](/bitcoin-bitcoin/6/) boost::detail::forward::operator()() /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:1388:32 (test_bitcoin+0x24f35c)
22    [#7](/bitcoin-bitcoin/7/) boost::detail::function::function_obj_invoker0<boost::detail::forward, int>::invoke(boost::detail::function::function_buffer&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:137:18 (test_bitcoin+0x24f35c)
23    [#8](/bitcoin-bitcoin/8/) boost::function0<int>::operator()() const /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:763:14 (test_bitcoin+0x1e3384) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
24    [#9](/bitcoin-bitcoin/9/) int boost::detail::do_invoke<boost::shared_ptr<boost::detail::translator_holder_base>, boost::function<int ()>>(boost::shared_ptr<boost::detail::translator_holder_base> const&, boost::function<int ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:301:30 (test_bitcoin+0x1e3384)
25    [#10](/bitcoin-bitcoin/10/) boost::execution_monitor::catch_signals(boost::function<int ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:903:16 (test_bitcoin+0x1e3384)
26    [#11](/bitcoin-bitcoin/11/) boost::execution_monitor::execute(boost::function<int ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:1301:16 (test_bitcoin+0x1e367c) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
27    [#12](/bitcoin-bitcoin/12/) boost::execution_monitor::vexecute(boost::function<void ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:1397:5 (test_bitcoin+0x1dcec0) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
28    [#13](/bitcoin-bitcoin/13/) boost::unit_test::unit_test_monitor_t::execute_and_translate(boost::function<void ()> const&, unsigned long) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/unit_test_monitor.ipp:49:9 (test_bitcoin+0x1dcec0)
29    [#14](/bitcoin-bitcoin/14/) boost::unit_test::framework::state::execute_test_tree(unsigned long, unsigned long, boost::unit_test::framework::state::random_generator_helper const*) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:815:44 (test_bitcoin+0x20cdfc) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
30    [#15](/bitcoin-bitcoin/15/) boost::unit_test::framework::state::execute_test_tree(unsigned long, unsigned long, boost::unit_test::framework::state::random_generator_helper const*) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:784:58 (test_bitcoin+0x20d128) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
31    [#16](/bitcoin-bitcoin/16/) boost::unit_test::framework::state::execute_test_tree(unsigned long, unsigned long, boost::unit_test::framework::state::random_generator_helper const*) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:784:58 (test_bitcoin+0x20d128) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
32    [#17](/bitcoin-bitcoin/17/) boost::unit_test::framework::run(unsigned long, bool) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:1722:29 (test_bitcoin+0x1dbe64) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
33    [#18](/bitcoin-bitcoin/18/) boost::unit_test::unit_test_main(boost::unit_test::test_suite* (*)(int, char**), int, char**) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/unit_test_main.ipp:250:9 (test_bitcoin+0x1f57c8) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
34    [#19](/bitcoin-bitcoin/19/) main /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/unit_test_main.ipp:306:12 (test_bitcoin+0x1f5d74) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
35
36  Previous read of size 8 at 0xfffffee67968 by thread T4:
37    [#0](/bitcoin-bitcoin/0/) BaseIndex::ThreadSync() src/index/base.cpp:217:18 (test_bitcoin+0xc55ba0) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
38    [#1](/bitcoin-bitcoin/1/) BaseIndex::Start()::$_0::operator()() const src/index/base.cpp:404:73 (test_bitcoin+0xc59324) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
39    [#2](/bitcoin-bitcoin/2/) decltype(std::declval<BaseIndex::Start()::$_0&>()()) std::__1::__invoke[abi:v160000]<BaseIndex::Start()::$_0&>(BaseIndex::Start()::$_0&) /usr/lib/llvm-16/bin/../include/c++/v1/__functional/invoke.h:394:23 (test_bitcoin+0xc59324)
40    [#3](/bitcoin-bitcoin/3/) void std::__1::__invoke_void_return_wrapper<void, true>::__call<BaseIndex::Start()::$_0&>(BaseIndex::Start()::$_0&) /usr/lib/llvm-16/bin/../include/c++/v1/__functional/invoke.h:487:9 (test_bitcoin+0xc59324)
41    [#4](/bitcoin-bitcoin/4/) std::__1::__function::__alloc_func<BaseIndex::Start()::$_0, std::__1::allocator<BaseIndex::Start()::$_0>, void ()>::operator()[abi:v160000]() /usr/lib/llvm-16/bin/../include/c++/v1/__functional/function.h:185:16 (test_bitcoin+0xc59324)
42    [#5](/bitcoin-bitcoin/5/) std::__1::__function::__func<BaseIndex::Start()::$_0, std::__1::allocator<BaseIndex::Start()::$_0>, void ()>::operator()() /usr/lib/llvm-16/bin/../include/c++/v1/__functional/function.h:356:12 (test_bitcoin+0xc59324)
43    [#6](/bitcoin-bitcoin/6/) std::__1::__function::__value_func<void ()>::operator()[abi:v160000]() const /usr/lib/llvm-16/bin/../include/c++/v1/__functional/function.h:510:16 (test_bitcoin+0x10cbd30) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
44    [#7](/bitcoin-bitcoin/7/) std::__1::function<void ()>::operator()() const /usr/lib/llvm-16/bin/../include/c++/v1/__functional/function.h:1156:12 (test_bitcoin+0x10cbd30)
45    [#8](/bitcoin-bitcoin/8/) util::TraceThread(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>) src/util/thread.cpp:21:9 (test_bitcoin+0x10cbd30)
46    [#9](/bitcoin-bitcoin/9/) decltype(std::declval<void (*)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>)>()(std::declval<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>>(), std::declval<BaseIndex::Start()::$_0>())) std::__1::__invoke[abi:v160000]<void (*)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>, BaseIndex::Start()::$_0>(void (*&&)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>&&, BaseIndex::Start()::$_0&&) /usr/lib/llvm-16/bin/../include/c++/v1/__functional/invoke.h:394:23 (test_bitcoin+0xc58e70) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
47    [#10](/bitcoin-bitcoin/10/) void std::__1::__thread_execute[abi:v160000]<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>, BaseIndex::Start()::$_0, 2ul, 3ul>(std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>, BaseIndex::Start()::$_0>&, std::__1::__tuple_indices<2ul, 3ul>) /usr/lib/llvm-16/bin/../include/c++/v1/thread:282:5 (test_bitcoin+0xc58e70)
48    [#11](/bitcoin-bitcoin/11/) void* std::__1::__thread_proxy[abi:v160000]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>, BaseIndex::Start()::$_0>>(void*) /usr/lib/llvm-16/bin/../include/c++/v1/thread:293:5 (test_bitcoin+0xc58e70)
49
50  Location is stack of main thread.
51
52  Location is global '??' at 0xfffffee4a000 ([stack]+0x1d968)
53
54  Thread T4 'b-txindex' (tid=24147, running) created by main thread at:
55    [#0](/bitcoin-bitcoin/0/) pthread_create <null> (test_bitcoin+0x13776c) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
56    [#1](/bitcoin-bitcoin/1/) std::__1::__libcpp_thread_create[abi:v160000](unsigned long*, void* (*)(void*), void*) /usr/lib/llvm-16/bin/../include/c++/v1/__threading_support:378:10 (test_bitcoin+0xc58b00) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
57    [#2](/bitcoin-bitcoin/2/) std::__1::thread::thread<void (*)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&, BaseIndex::Start()::$_0, void>(void (*&&)(std::__1::basic_string_view<char, std::__1::char_traits<char>>, std::__1::function<void ()>), std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&, BaseIndex::Start()::$_0&&) /usr/lib/llvm-16/bin/../include/c++/v1/thread:309:16 (test_bitcoin+0xc58b00)
58    [#3](/bitcoin-bitcoin/3/) BaseIndex::Start() src/index/base.cpp:404:21 (test_bitcoin+0xc58b00)
59    [#4](/bitcoin-bitcoin/4/) txindex_tests::txindex_initial_sync::test_method() src/test/txindex_tests.cpp:32:5 (test_bitcoin+0x7c18d8) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
60    [#5](/bitcoin-bitcoin/5/) txindex_tests::txindex_initial_sync_invoker() src/test/txindex_tests.cpp:17:1 (test_bitcoin+0x7c0f78) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
61    [#6](/bitcoin-bitcoin/6/) boost::detail::function::void_function_invoker0<void (*)(), void>::invoke(boost::detail::function::function_buffer&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:117:11 (test_bitcoin+0x2b78e8) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
62    [#7](/bitcoin-bitcoin/7/) boost::function0<void>::operator()() const /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:763:14 (test_bitcoin+0x24f35c) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
63    [#8](/bitcoin-bitcoin/8/) boost::detail::forward::operator()() /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:1388:32 (test_bitcoin+0x24f35c)
64    [#9](/bitcoin-bitcoin/9/) boost::detail::function::function_obj_invoker0<boost::detail::forward, int>::invoke(boost::detail::function::function_buffer&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:137:18 (test_bitcoin+0x24f35c)
65    [#10](/bitcoin-bitcoin/10/) boost::function0<int>::operator()() const /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/function/function_template.hpp:763:14 (test_bitcoin+0x1e3384) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
66    [#11](/bitcoin-bitcoin/11/) int boost::detail::do_invoke<boost::shared_ptr<boost::detail::translator_holder_base>, boost::function<int ()>>(boost::shared_ptr<boost::detail::translator_holder_base> const&, boost::function<int ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:301:30 (test_bitcoin+0x1e3384)
67    [#12](/bitcoin-bitcoin/12/) boost::execution_monitor::catch_signals(boost::function<int ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:903:16 (test_bitcoin+0x1e3384)
68    [#13](/bitcoin-bitcoin/13/) boost::execution_monitor::execute(boost::function<int ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:1301:16 (test_bitcoin+0x1e367c) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
69    [#14](/bitcoin-bitcoin/14/) boost::execution_monitor::vexecute(boost::function<void ()> const&) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/execution_monitor.ipp:1397:5 (test_bitcoin+0x1dcec0) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
70    [#15](/bitcoin-bitcoin/15/) boost::unit_test::unit_test_monitor_t::execute_and_translate(boost::function<void ()> const&, unsigned long) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/unit_test_monitor.ipp:49:9 (test_bitcoin+0x1dcec0)
71    [#16](/bitcoin-bitcoin/16/) boost::unit_test::framework::state::execute_test_tree(unsigned long, unsigned long, boost::unit_test::framework::state::random_generator_helper const*) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:815:44 (test_bitcoin+0x20cdfc) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
72    [#17](/bitcoin-bitcoin/17/) boost::unit_test::framework::state::execute_test_tree(unsigned long, unsigned long, boost::unit_test::framework::state::random_generator_helper const*) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:784:58 (test_bitcoin+0x20d128) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
73    [#18](/bitcoin-bitcoin/18/) boost::unit_test::framework::state::execute_test_tree(unsigned long, unsigned long, boost::unit_test::framework::state::random_generator_helper const*) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:784:58 (test_bitcoin+0x20d128) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
74    [#19](/bitcoin-bitcoin/19/) boost::unit_test::framework::run(unsigned long, bool) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/framework.ipp:1722:29 (test_bitcoin+0x1dbe64) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
75    [#20](/bitcoin-bitcoin/20/) boost::unit_test::unit_test_main(boost::unit_test::test_suite* (*)(int, char**), int, char**) /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/unit_test_main.ipp:250:9 (test_bitcoin+0x1f57c8) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
76    [#21](/bitcoin-bitcoin/21/) main /home/fedora/bitcoin/depends/aarch64-unknown-linux-gnu/include/boost/test/impl/unit_test_main.ipp:306:12 (test_bitcoin+0x1f5d74) (BuildId: 4e139378821749f690b2477a97607af03b8272e9)
77
78SUMMARY: ThreadSanitizer: data race on vptr (ctor/dtor vs virtual call) src/index/base.cpp:80:1 in BaseIndex::~BaseIndex()
79==================
80
81real	30m28.818s
82user	0m1.731s
83sys	0m1.874s

maflcko commented at 2:56 pm on March 28, 2023: member

Reproducible? If yes, what are the steps to reproduce?

fanquake commented at 2:58 pm on March 28, 2023: member

Reproducible

100%. Running time FILE_ENV="./ci/test/00_setup_env_native_tsan.sh" ./ci/test_run_all.sh on a aarch64 machine running Fedora 37.

fanquake commented at 4:05 pm on April 5, 2023: member

Retesting this on master (04595484d97100a50c146e5fc080319d9e0f5ca4). 1 line missing from the above output, which is dumped out in the test failure output before the test is re-run is libc++abi: Pure virtual function called!:

02023-04-05T15:47:47.686929Z (mocktime: 2020-08-31T15:34:12Z) [basic block filter index] [util/thread.cpp:20] [TraceThread] basic block filter index thread start
1test/blockfilter_index_tests.cpp(147): fatal error: in "blockfilter_index_tests/blockfilter_index_initial_sync": critical check time_start + timeout_ms > GetTimeMillis() has failed
2libc++abi: Pure virtual function called!
3make[3]: *** [Makefile:21866: test/blockfilter_index_tests.cpp.test] Error 1

mzumsande commented at 7:35 pm on April 5, 2023: contributor

I think that the data race is not the root cause, but happens as a result of the absolute timeout https://github.com/bitcoin/bitcoin/blob/04595484d97100a50c146e5fc080319d9e0f5ca4/src/test/txindex_tests.cpp#L35 not being sufficient, because the test environment is too slow for whatever reason. In this case, the BOOST_REQUIRE in https://github.com/bitcoin/bitcoin/blob/04595484d97100a50c146e5fc080319d9e0f5ca4/src/test/txindex_tests.cpp#L38 fails, and the index isn’t terminated correctly (by waiting for ThreadSync to stop, as it would be done in txindex.Stop() below if the boost assert wasn’t hit)

I could reproduce the error and the data race on my machine (x86_64 Ubuntu) by setting timeout_ms = 0 in the line above.

As a fix, I think that we should wait longer for the sync to finish, by either getting rid of the constant timeout (though that would mean it could run forever if something was wrong) or at least increasing it significantly. I’ll look into that.

mzumsande commented at 8:28 pm on April 5, 2023: contributor

Hmm, the existing timeout of 10 seconds seems plenty for the sync process, which takes just a few milliseconds on my computer. @fanquake would a higher timeout fix this in your environment? Are you doing some extreme parallelization or someting, such that the test is simply that slow? Or is there possibly some other reason that prevents the Index sync from finishing on aarch64, so that bumping the timeout wouldn’t help?

fanquake commented at 10:46 am on April 12, 2023: member

would a higher timeout fix this in your environment?

I bumped the timeout, and it didn’t seem to make any difference.

Are you doing some extreme parallelization or someting, such that the test is simply that slow?

Nothing like that, and the machine isn’t particularly slow. i.e it has no issue running various valgrind and other CI jobs. I’ll take another look.

mzumsande commented at 2:25 pm on April 12, 2023: contributor

Hmm, then my guess that it could be the timeout was probably wrong. Could you run the test in isolation with -- -printtoconsole and post the log?

maflcko commented at 2:44 pm on April 13, 2023: member

Reproducible

100%. Running time FILE_ENV="./ci/test/00_setup_env_native_tsan.sh" ./ci/test_run_all.sh on a aarch64 machine running Fedora 37.

Idk. Locally this fails for me when building bdb:

  0Extracting bdb...
  1/root/bitcoin-core/depends/sources/db-4.8.30.NC.tar.gz: OK
  2Preprocessing bdb...
  3Configuring bdb...
  4patching file dbinc/atomic.h
  5patching file mp/mp_fget.c
  6patching file mp/mp_mvcc.c
  7patching file mp/mp_region.c
  8patching file mutex/mut_method.c
  9patching file mutex/mut_tas.c
 10checking build system type... aarch64-unknown-linux-gnu
 11checking host system type... aarch64-unknown-linux-gnu
 12checking if building in the top-level or dist directories... no
 13checking if --disable-cryptography option specified... no
 14checking if --disable-hash option specified... no
 15checking if --disable-partition option specified... no
 16checking if --disable-compression option specified... no
 17checking if --disable-mutexsupport option specified... no
 18checking if --disable-atomicsupport option specified... no
 19checking if --disable-queue option specified... no
 20checking if --disable-replication option specified... yes
 21checking if --disable-statistics option specified... no
 22checking if --disable-verify option specified... no
 23checking if --enable-compat185 option specified... no
 24checking if --enable-cxx option specified... yes
 25checking if --enable-debug option specified... no
 26checking if --enable-debug_rop option specified... no
 27checking if --enable-debug_wop option specified... no
 28checking if --enable-diagnostic option specified... no
 29checking if --enable-dump185 option specified... no
 30checking if --enable-java option specified... no
 31checking if --enable-mingw option specified... no
 32checking if --enable-o_direct option specified... no
 33checking if --enable-posixmutexes option specified... no
 34checking if --enable-rpc option specified... no
 35checking if --enable-smallbuild option specified... no
 36checking if --enable-stl option specified... no
 37checking if --enable-tcl option specified... no
 38checking if --enable-test option specified... no
 39checking if --enable-uimutexes option specified... no
 40checking if --enable-umrw option specified... no
 41checking if --with-mutex=MUTEX option specified... no
 42checking if --with-tcl=DIR option specified... no
 43checking if --with-uniquename=NAME option specified... no
 44checking for aarch64-unknown-linux-gnu-chmod... no
 45checking for chmod... chmod
 46checking for aarch64-unknown-linux-gnu-cp... no
 47checking for cp... cp
 48checking for aarch64-unknown-linux-gnu-ln... no
 49checking for ln... ln
 50checking for aarch64-unknown-linux-gnu-mkdir... no
 51checking for mkdir... mkdir
 52checking for aarch64-unknown-linux-gnu-rm... no
 53checking for rm... rm
 54checking for aarch64-unknown-linux-gnu-sh... no
 55checking for sh... /usr/bin/sh
 56checking for a BSD-compatible install... /usr/bin/install -c
 57checking for aarch64-unknown-linux-gnu-cc... clang-16
 58checking whether the C compiler works... yes
 59checking for C compiler default output file name... a.out
 60checking for suffix of executables... 
 61checking whether we are cross compiling... no
 62checking for suffix of object files... o
 63checking whether we are using the GNU C compiler... yes
 64checking whether clang-16 accepts -g... yes
 65checking for clang-16 option to accept ISO C89... none needed
 66checking for an ANSI C-conforming const... yes
 67checking for inline... inline
 68checking whether we are using the GNU C++ compiler... yes
 69checking whether clang++-16 -stdlib=libc++ accepts -g... yes
 70checking how to run the C++ preprocessor... clang++-16 -stdlib=libc++ -E
 71checking whether C++ supports the ISO C++ standard includes... yes
 72checking whether we are using gcc version 2.96... no
 73checking for a sed that does not truncate output... /usr/bin/sed
 74checking for grep that handles long lines and -e... /usr/bin/grep
 75checking for egrep... /usr/bin/grep -E
 76checking for fgrep... /usr/bin/grep -F
 77checking for ld used by clang-16... /usr/bin/ld
 78checking if the linker (/usr/bin/ld) is GNU ld... yes
 79checking for BSD- or MS-compatible name lister (nm)... nm
 80checking the name lister (nm) interface... BSD nm
 81checking whether ln -s works... yes
 82checking the maximum length of command line arguments... 1572864
 83checking whether the shell understands some XSI constructs... yes
 84checking whether the shell understands "+="... yes
 85checking for /usr/bin/ld option to reload object files... -r
 86checking for aarch64-unknown-linux-gnu-objdump... no
 87checking for objdump... objdump
 88checking how to recognize dependent libraries... pass_all
 89checking for aarch64-unknown-linux-gnu-ar... ar
 90checking for aarch64-unknown-linux-gnu-strip... no
 91checking for strip... strip
 92checking for aarch64-unknown-linux-gnu-ranlib... ranlib
 93checking command to parse nm output from clang-16 object... ok
 94checking how to run the C preprocessor... clang-16 -E
 95checking for ANSI C header files... yes
 96checking for sys/types.h... yes
 97checking for sys/stat.h... yes
 98checking for stdlib.h... yes
 99checking for string.h... yes
100checking for memory.h... yes
101checking for strings.h... yes
102checking for inttypes.h... yes
103checking for stdint.h... yes
104checking for unistd.h... yes
105checking for dlfcn.h... yes
106checking whether we are using the GNU C++ compiler... (cached) yes
107checking whether clang++-16 -stdlib=libc++ accepts -g... (cached) yes
108checking how to run the C++ preprocessor... clang++-16 -stdlib=libc++ -E
109checking for objdir... .libs
110checking if clang-16 supports -fno-rtti -fno-exceptions... yes
111checking for clang-16 option to produce PIC... -fPIC -DPIC
112checking if clang-16 PIC flag -fPIC -DPIC works... yes
113checking if clang-16 static flag -static works... yes
114checking if clang-16 supports -c -o file.o... yes
115checking if clang-16 supports -c -o file.o... (cached) yes
116checking whether the clang-16 linker (/usr/bin/ld) supports shared libraries... yes
117checking dynamic linker characteristics... GNU/Linux ld.so
118checking how to hardcode library paths into programs... immediate
119checking whether stripping libraries is possible... yes
120checking if libtool supports shared libraries... yes
121checking whether to build shared libraries... no
122checking whether to build static libraries... yes
123checking for ld used by clang++-16 -stdlib=libc++... /usr/bin/ld
124checking if the linker (/usr/bin/ld) is GNU ld... yes
125checking whether the clang++-16 -stdlib=libc++ linker (/usr/bin/ld) supports shared libraries... yes
126checking for clang++-16 -stdlib=libc++ option to produce PIC... -fPIC -DPIC
127checking if clang++-16 -stdlib=libc++ PIC flag -fPIC -DPIC works... yes
128checking if clang++-16 -stdlib=libc++ static flag -static works... yes
129checking if clang++-16 -stdlib=libc++ supports -c -o file.o... yes
130checking if clang++-16 -stdlib=libc++ supports -c -o file.o... (cached) yes
131checking whether the clang++-16 -stdlib=libc++ linker (/usr/bin/ld) supports shared libraries... yes
132checking dynamic linker characteristics... GNU/Linux ld.so
133checking how to hardcode library paths into programs... immediate
134checking SOSUFFIX from libtool... .so
135checking MODSUFFIX from libtool... .so
136checking JMODSUFFIX from libtool... .so
137checking whether stat file-mode macros are broken... no
138checking whether time.h and sys/time.h may both be included... yes
139checking for dirent.h that defines DIR... yes
140checking for library containing opendir... none required
141checking execinfo.h usability... yes
142checking execinfo.h presence... yes
143checking for execinfo.h... yes
144checking sys/select.h usability... yes
145checking sys/select.h presence... yes
146checking for sys/select.h... yes
147checking sys/socket.h usability... yes
148checking sys/socket.h presence... yes
149checking for sys/socket.h... yes
150checking sys/time.h usability... yes
151checking sys/time.h presence... yes
152checking for sys/time.h... yes
153checking for struct stat.st_blksize... yes
154checking for inttypes.h... (cached) yes
155checking for stdint.h... yes
156checking if stdint.h can be used by C++... yes
157checking stddef.h usability... yes
158checking stddef.h presence... yes
159checking for stddef.h... yes
160checking for unistd.h... (cached) yes
161checking size of char... 1
162checking size of unsigned char... 1
163checking size of short... 2
164checking size of unsigned short... 2
165checking size of int... 4
166checking size of unsigned int... 4
167checking size of long... 8
168checking size of unsigned long... 8
169checking size of long long... 8
170checking size of unsigned long long... 8
171checking size of char *... 8
172checking for u_char... yes
173checking for u_short... yes
174checking for u_int... yes
175checking for u_long... yes
176checking for u_int8_t... yes
177checking for u_int16_t... yes
178checking for int16_t... yes
179checking for u_int32_t... yes
180checking for int32_t... yes
181checking for u_int64_t... yes
182checking for int64_t... yes
183checking for FILE *... yes
184checking for off_t... yes
185checking for pid_t... yes
186checking for size_t... yes
187checking for time_t... yes
188checking size of size_t... 8
189checking for ssize_t... yes
190checking for uintmax_t... yes
191checking for uintptr_t... yes
192checking for socklen_t... yes
193checking for ANSI C exit success/failure values... yes
194checking for getopt optreset variable... no
195checking for mutexes... UNIX/fcntl
196configure: WARNING: NO SHARED LATCH IMPLEMENTATION FOUND FOR THIS PLATFORM.
197configure: error: Unable to find a mutex implementation
198make: *** [funcs.mk:292: /root/bitcoin-core/depends/aarch64-unknown-linux-gnu/.bdb_stamp_configured] Error 1
199make: Leaving directory '/root/bitcoin-core/depends'

fanquake commented at 2:45 pm on April 13, 2023: member

Idk. Locally this fails for me when building bdb:

Yea. You’ll have to use NO_BDB=1, or fix BDB.

maflcko commented at 4:09 pm on April 13, 2023: member

Ok, it is passing for me with NO_BDB. Could be a hardware issue on your side.

 0# lscpu
 1Architecture:            aarch64
 2  CPU op-mode(s):        32-bit, 64-bit
 3  Byte Order:            Little Endian
 4CPU(s):                  4
 5  On-line CPU(s) list:   0-3
 6Vendor ID:               ARM
 7  BIOS Vendor ID:        QEMU
 8  Model name:            Neoverse-N1
 9    BIOS Model name:     NotSpecified  CPU @ 2.0GHz
10    BIOS CPU family:     1
11    Model:               1
12    Thread(s) per core:  1
13    Core(s) per cluster: 4
14    Socket(s):           1
15    Cluster(s):          1
16    Stepping:            r3p1
17    BogoMIPS:            50.00
18    Flags:               fp asimd evtstrm aes pmull sha1 sha2 crc32 atomics fphp asimdhp cpuid asimdrdm lrcpc dcpop asimddp ssbs
19NUMA:                    
20  NUMA node(s):          1
21  NUMA node0 CPU(s):     0-3
22Vulnerabilities:         
23  Itlb multihit:         Not affected
24  L1tf:                  Not affected
25  Mds:                   Not affected
26  Meltdown:              Not affected
27  Mmio stale data:       Not affected
28  Retbleed:              Not affected
29  Spec store bypass:     Mitigation; Speculative Store Bypass disabled via prctl
30  Spectre v1:            Mitigation; __user pointer sanitization
31  Spectre v2:            Mitigation; CSV2, BHB
32  Srbds:                 Not affected
33  Tsx async abort:       Not affected

maflcko commented at 4:12 pm on April 13, 2023: member

I am using podman, but that shouldn’t matter

maflcko added the label Questions and Help on Apr 13, 2023

maflcko added the label Tests on Apr 13, 2023

maflcko commented at 8:45 am on April 14, 2023: member

Maybe you can share your CPU model/hardware, so that someone can try on that, but other than that I am not sure what to do here

fanquake commented at 8:51 am on April 14, 2023: member

Maybe you can share your CPU model/hardware,

It’s the same as yours above:

 0Architecture:           aarch64
 1  CPU op-mode(s):       32-bit, 64-bit
 2  Byte Order:           Little Endian
 3CPU(s):                 4
 4  On-line CPU(s) list:  0-3
 5Vendor ID:              ARM
 6  Model name:           Neoverse-N1
 7    Model:              1
 8    Thread(s) per core: 1
 9    Core(s) per socket: 4
10    Socket(s):          1
11    Stepping:           r3p1
12    BogoMIPS:           243.75
13    Flags:              fp asimd evtstrm aes pmull sha1 sha2 crc32 atomics fphp asimdhp cpuid asimdrdm lrcpc dcpop asimddp ssbs
14Caches (sum of all):    
15  L1d:                  256 KiB (4 instances)
16  L1i:                  256 KiB (4 instances)
17  L2:                   4 MiB (4 instances)
18  L3:                   32 MiB (1 instance)
19NUMA:                   
20  NUMA node(s):         1
21  NUMA node0 CPU(s):    0-3
22Vulnerabilities:        
23  Itlb multihit:        Not affected
24  L1tf:                 Not affected
25  Mds:                  Not affected
26  Meltdown:             Not affected
27  Mmio stale data:      Not affected
28  Retbleed:             Not affected
29  Spec store bypass:    Mitigation; Speculative Store Bypass disabled via prctl
30  Spectre v1:           Mitigation; __user pointer sanitization
31  Spectre v2:           Mitigation; CSV2, BHB
32  Srbds:                Not affected
33  Tsx async abort:      Not affected

fanquake commented at 12:39 pm on April 14, 2023: member

Hmm, then my guess that it could be the timeout was probably wrong. Could you run the test in isolation with – -printtoconsole and post the log?

With the branch in #27462 (which just fixes BDB compilation), if i run the TSAN CI, it fails as it has been. However if I exec into the container after it fails, and run src/test/test_bitcoin --catch_system_errors=no -l test_suite -t blockfilter_index_tests, this issue does not reproduce.

maflcko commented at 1:28 pm on April 14, 2023: member

I also can not reproduce with:

0time bash -c 'RUN_UNIT_TESTS_SEQUENTIAL="true" RUN_UNIT_TESTS="false" RUN_FUNCTIONAL_TESTS=false CCACHE_SIZE=500M MAKEJOBS="-j9" FILE_ENV="./ci/test/00_setup_env_native_tsan.sh" ./ci/test_run_all.sh'

and diff:

 0diff --git a/ci/test/06_script_b.sh b/ci/test/06_script_b.sh
 1index f7dcbcee5..899c99119 100755
 2--- a/ci/test/06_script_b.sh
 3+++ b/ci/test/06_script_b.sh
 4@@ -29,7 +29,7 @@ if [ "$RUN_UNIT_TESTS" = "true" ]; then
 5 fi
 6 
 7 if [ "$RUN_UNIT_TESTS_SEQUENTIAL" = "true" ]; then
 8-  CI_EXEC "${TEST_RUNNER_ENV}" DIR_UNIT_TEST_DATA="${DIR_UNIT_TEST_DATA}" LD_LIBRARY_PATH="${DEPENDS_DIR}/${HOST}/lib" "${BASE_OUTDIR}/bin/test_bitcoin" --catch_system_errors=no -l test_suite
 9+  CI_EXEC "${TEST_RUNNER_ENV}" DIR_UNIT_TEST_DATA="${DIR_UNIT_TEST_DATA}" LD_LIBRARY_PATH="${DEPENDS_DIR}/${HOST}/lib" "${BASE_OUTDIR}/bin/test_bitcoin" --catch_system_errors=no -l test_suite -t blockfilter_index_tests
10 fi
11 
12 if [ "$RUN_FUNCTIONAL_TESTS" = "true" ]; then
13diff --git a/depends/packages/bdb.mk b/depends/packages/bdb.mk
14index d60733605..9f5a92501 100644
15--- a/depends/packages/bdb.mk
16+++ b/depends/packages/bdb.mk
17@@ -14,7 +14,7 @@ $(package)_config_opts_freebsd=--with-pic
18 $(package)_config_opts_netbsd=--with-pic
19 $(package)_config_opts_openbsd=--with-pic
20 $(package)_config_opts_android=--with-pic
21-$(package)_cflags+=-Wno-error=implicit-function-declaration -Wno-error=format-security
22+$(package)_cflags+=-Wno-error=implicit-function-declaration -Wno-error=format-security -Wno-error=implicit-int
23 $(package)_cppflags_freebsd=-D_XOPEN_SOURCE=600 -D__BSD_VISIBLE=1
24 $(package)_cppflags_netbsd=-D_XOPEN_SOURCE=600
25 $(package)_cppflags_openbsd=-D_XOPEN_SOURCE=600

maflcko commented at 2:20 pm on April 14, 2023: member

All I run into here is a bdb issue, which can be worked around with:

 0diff --git a/test/sanitizer_suppressions/tsan b/test/sanitizer_suppressions/tsan
 1index d33199127..35c6a5f95 100644
 2--- a/test/sanitizer_suppressions/tsan
 3+++ b/test/sanitizer_suppressions/tsan
 4@@ -23,7 +23,7 @@ race:src/qt/test/*
 5 deadlock:src/qt/test/*
 6 
 7 # External libraries
 8-deadlock:libdb
 9+deadlock:__db_pthread_mutex_lock
10 race:libzmq
11 
12 # Intermittent issues

furszy commented at 3:06 pm on April 14, 2023: member

Not really a fix if there is something else going on but.. could use https://github.com/furszy/bitcoin-core/commit/8495c852ebe199a96a4e205937861b76f54227eb (quick and dirty) to remove the active-wait timeout error.

DrahtBot commented at 2:31 pm on May 12, 2023: contributor

I ran into this as well:

 02023-05-12T12:24:59.051246Z (mocktime: 2020-08-31T15:34:11Z) [test] [node/miner.cpp:162] [CreateNewBlock] CreateNewBlock(): block weight: 940 txs: 0 fees: 0 sigops 400
 12023-05-12T12:24:59.051432Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2159] [ConnectBlock] [bench]     - Sanity checks: 0.01ms [0.00s (0.00ms/blk)]
 22023-05-12T12:24:59.051514Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2261] [ConnectBlock] [bench]     - Fork checks: 0.09ms [0.02s (0.09ms/blk)]
 32023-05-12T12:24:59.051591Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2351] [ConnectBlock] [bench]       - Connect 1 transactions: 0.07ms (0.071ms/tx, 0.000ms/txin) [0.02s (0.08ms/blk)]
 42023-05-12T12:24:59.051658Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2369] [ConnectBlock] [bench]     - Verify 0 txins: 0.14ms (0.000ms/txin) [0.03s (0.15ms/blk)]
 52023-05-12T12:24:59.051782Z (mocktime: 2020-08-31T15:34:11Z) [test] [node/miner.cpp:181] [CreateNewBlock] [bench] CreateNewBlock() packages: 0.03ms (0 packages, 0 updated descendants), validity: 0.60ms (total 0.63ms)
 62023-05-12T12:24:59.052016Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:3870] [AcceptBlockHeader] Saw new header hash=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191 height=100
 72023-05-12T12:24:59.052580Z (mocktime: 2020-08-31T15:34:11Z) [test] [validationinterface.cpp:260] [NewPoWValidBlock] [validation] NewPoWValidBlock: block hash=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191
 82023-05-12T12:24:59.053339Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2831] [ConnectTip] [bench]   - Using cached block
 92023-05-12T12:24:59.053400Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2842] [ConnectTip] [bench]   - Load block from disk: 0.05ms [0.01s (0.03ms/blk)]
102023-05-12T12:24:59.053525Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2159] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)]
112023-05-12T12:24:59.053604Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2261] [ConnectBlock] [bench]     - Fork checks: 0.08ms [0.02s (0.09ms/blk)]
122023-05-12T12:24:59.053686Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2351] [ConnectBlock] [bench]       - Connect 1 transactions: 0.08ms (0.076ms/tx, 0.000ms/txin) [0.02s (0.08ms/blk)]
132023-05-12T12:24:59.053785Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2369] [ConnectBlock] [bench]     - Verify 0 txins: 0.18ms (0.000ms/txin) [0.03s (0.15ms/blk)]
142023-05-12T12:24:59.053947Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2383] [ConnectBlock] [bench]     - Write undo data: 0.16ms [0.02s (0.11ms/blk)]
152023-05-12T12:24:59.054000Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2398] [ConnectBlock] [bench]     - Index writing: 0.06ms [0.01s (0.03ms/blk)]
162023-05-12T12:24:59.054061Z (mocktime: 2020-08-31T15:34:11Z) [test] [validationinterface.cpp:255] [BlockChecked] [validation] BlockChecked: block hash=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191 state=Valid
172023-05-12T12:24:59.054118Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2858] [ConnectTip] [bench]   - Connect total: 0.73ms [0.08s (0.38ms/blk)]
182023-05-12T12:24:59.054336Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2867] [ConnectTip] [bench]   - Flush: 0.21ms [0.02s (0.11ms/blk)]
192023-05-12T12:24:59.054409Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2877] [ConnectTip] [bench]   - Writing chainstate: 0.08ms [0.01s (0.04ms/blk)]
202023-05-12T12:24:59.055286Z (mocktime: 2020-08-31T15:34:11Z) [test] [policy/fees.cpp:667] [processBlock] [estimatefee] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
212023-05-12T12:24:59.055419Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2637] [UpdateTipLog] UpdateTip: new best=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191 height=100 version=0x20000000 log2_work=7.658211 tx=101 date='2020-08-31T15:34:11Z' progress=1.000000 cache=0.3MiB(100txo)
222023-05-12T12:24:59.055471Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2893] [ConnectTip] [bench]   - Connect postprocess: 1.06ms [0.11s (0.54ms/blk)]
232023-05-12T12:24:59.055516Z (mocktime: 2020-08-31T15:34:11Z) [test] [validation.cpp:2897] [ConnectTip] [bench] - Connect block: 2.13ms [0.22s (1.09ms/blk)]
242023-05-12T12:24:59.055585Z (mocktime: 2020-08-31T15:34:11Z) [test] [txmempool.cpp:659] [check] [mempool] Checking mempool with 0 transactions and 0 inputs
252023-05-12T12:24:59.055797Z (mocktime: 2020-08-31T15:34:11Z) [test] [validationinterface.cpp:232] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191 block height=100
262023-05-12T12:24:59.055935Z (mocktime: 2020-08-31T15:34:11Z) [scheduler] [validationinterface.cpp:232] [operator()] [validation] BlockConnected: block hash=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191 block height=100
272023-05-12T12:24:59.056065Z (mocktime: 2020-08-31T15:34:11Z) [test] [validationinterface.cpp:204] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191 fork block hash=68aef0c7c1c2cc15ca20a558ea1d6e66aecc1d6398bddea75e4c031cb79cc07e (in IBD=false)
282023-05-12T12:24:59.056203Z (mocktime: 2020-08-31T15:34:11Z) [scheduler] [validationinterface.cpp:204] [operator()] [validation] UpdatedBlockTip: new block hash=571d80a9967ae599cec0448b0b0ba1cfb606f584d8069bd7166b86854ba7a191 fork block hash=68aef0c7c1c2cc15ca20a558ea1d6e66aecc1d6398bddea75e4c031cb79cc07e (in IBD=false)
292023-05-12T12:24:59.068884Z (mocktime: 2020-08-31T15:34:12Z) [test] [dbwrapper.cpp:158] [CDBWrapper] Opened LevelDB successfully
302023-05-12T12:24:59.068996Z (mocktime: 2020-08-31T15:34:12Z) [test] [dbwrapper.cpp:183] [CDBWrapper] Using obfuscation key for /tmp/test_common_Bitcoin Core/2ce9328e486919722790b84cffa4be425cf708aac6a4db24624ed0ff4e487f1d/regtest/indexes/blockfilter/basic/db: 0000000000000000
31test/blockfilter_index_tests.cpp(148): fatal error: in "blockfilter_index_tests/blockfilter_index_initial_sync": critical check time_start + timeout > SteadyClock::now() has failed
32libc++abi: Pure virtual function called!
332023-05-12T12:24:59.113190Z (mocktime: 2020-08-31T15:34:12Z) [basic block filter index] [util/thread.cpp:20] [TraceThread] basic block filter index thread start
34make[3]: Leaving directory '/root/b-c-ci/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/src'
35make[2]: *** [Makefile:20096: check-am] Error 2
36make[2]: Leaving directory '/root/b-c-ci/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/src'
37make[1]: *** [Makefile:19761: check-recursive] Error 1
38make[1]: Leaving directory '/root/b-c-ci/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/src'
39make: *** [Makefile:816: check-recursive] Error 1
40Emulate Docker CLI using podman. Create /etc/containers/nodocker to quiet msg.

furszy commented at 2:42 pm on May 12, 2023: member

Is it me or DrahtBot is typing as a human?

maflcko commented at 9:09 am on May 24, 2023: member

Not really a fix if there is something else going on but.. could use furszy@8495c85 (quick and dirty) to remove the active-wait timeout error.

Mind opening a pull so that it can be reviewed and tested?

Review note: I don’t think you need to embed the exception into the promise. A thread (re-)throwing into void will lead to immediate abort anyway. It should be sufficient to replace [this] { ThreadSync(); } with [this] { ThreadSync(); p.set_value(); }

maflcko commented at 9:10 am on May 24, 2023: member

To reproduce locally, one can try to build with tsan, then run the functional tests in the background to eat all available CPU, then run the failing test case in the foreground in a loop until it fails.

furszy commented at 3:44 pm on May 26, 2023: member

Not really a fix if there is something else going on but.. could use furszy@8495c85 (quick and dirty) to remove the active-wait timeout error.

Mind opening a pull so that it can be reviewed and tested?

Sure. Need a bit more time and will do it. I’m already tackling few issues in the area (#27607 and #27720) and would be good to receive a bit more feedback there prior creating this new PR, so I don’t have to rework it some days after pushing it.

maflcko commented at 7:13 am on May 30, 2023: member

A quick hack in the meantime could be:

0sed -i 's/constexpr auto timeout{10s};/constexpr auto timeout{300s};/g' ./src/test/blockfilter_index_tests.cpp ./src/test/txindex_tests.cpp

maflcko commented at 7:20 am on June 23, 2023: member

Looks like there is a variation with ERROR: Commit: Failed to commit latest basic block filter index state?

https://cirrus-ci.com/task/6737719183802368?logs=ci#L4142

02023-06-22T20:05:34.892973Z (mocktime: 2020-08-31T15:34:12Z) [basic block filter index] [util/thread.cpp:20] [TraceThread] basic block filter index thread start
12023-06-22T20:05:55.312479Z (mocktime: 2020-08-31T15:34:12Z) [basic block filter index] [index/base.cpp:212] [ThreadSync] Syncing basic block filter index with block chain from height 0
22023-06-22T20:05:55.312843Z (mocktime: 2020-08-31T15:34:12Z) [basic block filter index] [logging.h:263] [error] ERROR: Commit: Failed to commit latest basic block filter index state
32023-06-22T20:05:55.313942Z (mocktime: 2020-08-31T15:34:12Z) [basic block filter index] [flatfile.cpp:69] [Allocate] [validation] Pre-allocating up to position 0x100000 in fltr00000.dat
4test/blockfilter_index_tests.cpp(148): fatal error: in "blockfilter_index_tests/blockfilter_index_initial_sync": critical check time_start + timeout > SteadyClock::now() has failed
5LLVMSymbolizer: error reading file: No such file or directory
6make[3]: *** [Makefile:22216: test/blockfilter_index_tests.cpp.test] Error 1

maflcko commented at 10:47 am on June 23, 2023: member

And the same without the error:

https://cirrus-ci.com/task/5505476792680448?logs=ci#L4221

02023-06-23T10:38:01.749709Z (mocktime: 2020-08-31T15:34:12Z) [txindex] [util/thread.cpp:20] [TraceThread] txindex thread start
1test/txindex_tests.cpp(38): fatal error: in "txindex_tests/txindex_initial_sync": critical check time_start + timeout > SteadyClock::now() has failed
2libc++abi: Pure virtual function called!
3make[3]: *** [Makefile:22216: test/txindex_tests.cpp.test] Error 1

maflcko commented at 10:25 am on June 28, 2023: member

This is getting too frequent. I recently encountered this 8 times in a row.

Maybe #27988 makes it less frequent for now, by only modifying test code?

furszy commented at 2:57 pm on June 28, 2023: member

Hmm interesting. #27607 is getting quite close now. It’s making some substantial changes to the index Init and Start code. Will rebase furszy@8495c85 on top and push it so we can try that one too.

mzumsande commented at 10:04 pm on June 28, 2023: contributor

Looks like there is a variation with ERROR: Commit: Failed to commit latest basic block filter index state?

And the same without the error:

It’s different tests for different indexes: txindex_tests/txindex_initial_sync fails without the Commit Error, blockfilter_index_tests/blockfilter_index_initial_sync fails with it (but same root cause obviously).

maflcko commented at 10:39 am on June 29, 2023: member

Looks like #27988 is a test-only fix for the initial issue reported here, and it increases consistency for now. I think it should be good to go, trivial to remove or rework in the future with a std::future-based approach.

fanquake closed this on Jun 30, 2023

sidhujag referenced this in commit dd1610ba46 on Jun 30, 2023

timemarkovqtum referenced this in commit 47ab00666e on Jan 30, 2024

bitcoin locked this on Jun 29, 2024

index: ThreadSanitizer: data race on vptr #27355