test: Potential deadlock in wallet_tests/CreateWalletFromFile #19049

Building master (df303ceb650521dc7b1ba91e0eea383c387a5860) on Linux Mint 19.3 (x86_64, bionic codebase):

$ ./configure --with-sanitizers=thread && make clean && make
$ TSAN_OPTIONS="suppressions=test/sanitizer_suppressions/tsan" ./src/test/test_bitcoin --run_test=wallet_tests/CreateWalletFromFile
Running 1 test case...
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
==================
WARNING: ThreadSanitizer: lock-order-inversion (potential deadlock) (pid=31793)
  Cycle in lock order graph: M134059 (0x7b6400004cc8) => M133094 (0x56527c390c60) => M134059

  Mutex M133094 acquired here while holding mutex M134059 in main thread:
    [#0](/bitcoin-bitcoin/0/) pthread_mutex_lock <null> (libtsan.so.0+0x3fadb)
    [#1](/bitcoin-bitcoin/1/) __gthread_mutex_lock /usr/include/x86_64-linux-gnu/c++/7/bits/gthr-default.h:748 (test_bitcoin+0xd17c11)
    [#2](/bitcoin-bitcoin/2/) __gthread_recursive_mutex_lock /usr/include/x86_64-linux-gnu/c++/7/bits/gthr-default.h:810 (test_bitcoin+0xd17c11)
    [#3](/bitcoin-bitcoin/3/) std::recursive_mutex::lock() /usr/include/c++/7/mutex:107 (test_bitcoin+0xd17c11)
    [#4](/bitcoin-bitcoin/4/) std::unique_lock<std::recursive_mutex>::lock() /usr/include/c++/7/bits/std_mutex.h:267 (test_bitcoin+0xd17c11)
    [#5](/bitcoin-bitcoin/5/) UniqueLock<AnnotatedMixin<std::recursive_mutex>, std::unique_lock<std::recursive_mutex> >::Enter(char const*, char const*, int) sync.h:131 (test_bitcoin+0xd17c11)
    [#6](/bitcoin-bitcoin/6/) UniqueLock<AnnotatedMixin<std::recursive_mutex>, std::unique_lock<std::recursive_mutex> >::UniqueLock(AnnotatedMixin<std::recursive_mutex>&, char const*, char const*, int, bool) sync.h:152 (test_bitcoin+0xd17c11)
    [#7](/bitcoin-bitcoin/7/) CWallet::CreateWalletFromFile(interfaces::Chain&, WalletLocation const&, bilingual_str&, std::vector<bilingual_str, std::allocator<bilingual_str> >&, unsigned long) wallet/wallet.cpp:4004 (test_bitcoin+0xd397de)
    [#8](/bitcoin-bitcoin/8/) TestLoadWallet wallet/test/wallet_tests.cpp:37 (test_bitcoin+0x703587)
    [#9](/bitcoin-bitcoin/9/) wallet_tests::CreateWalletFromFile::test_method() wallet/test/wallet_tests.cpp:782 (test_bitcoin+0x72013e)
    [#10](/bitcoin-bitcoin/10/) CreateWalletFromFile_invoker wallet/test/wallet_tests.cpp:700 (test_bitcoin+0x721452)
    [#11](/bitcoin-bitcoin/11/) boost::detail::function::void_function_invoker0<void (*)(), void>::invoke(boost::detail::function::function_buffer&) /usr/include/boost/function/function_template.hpp:118 (test_bitcoin+0xe05fb)
    [#12](/bitcoin-bitcoin/12/) boost::detail::function::function_obj_invoker0<boost::detail::forward, int>::invoke(boost::detail::function::function_buffer&) <null> (libboost_unit_test_framework.so.1.65.1+0x4b2cd)
    [#13](/bitcoin-bitcoin/13/) __libc_start_main <null> (libc.so.6+0x21b96)

    Hint: use TSAN_OPTIONS=second_deadlock_stack=1 to get more informative warning message

  Mutex M134059 acquired here while holding mutex M133094 in main thread:
    [#0](/bitcoin-bitcoin/0/) pthread_mutex_lock <null> (libtsan.so.0+0x3fadb)
    [#1](/bitcoin-bitcoin/1/) __gthread_mutex_lock /usr/include/x86_64-linux-gnu/c++/7/bits/gthr-default.h:748 (test_bitcoin+0x71e053)
    [#2](/bitcoin-bitcoin/2/) __gthread_recursive_mutex_lock /usr/include/x86_64-linux-gnu/c++/7/bits/gthr-default.h:810 (test_bitcoin+0x71e053)
    [#3](/bitcoin-bitcoin/3/) std::recursive_mutex::lock() /usr/include/c++/7/mutex:107 (test_bitcoin+0x71e053)
    [#4](/bitcoin-bitcoin/4/) AnnotatedMixin<std::recursive_mutex>::lock() sync.h:90 (test_bitcoin+0x71e053)
    [#5](/bitcoin-bitcoin/5/) operator() wallet/test/wallet_tests.cpp:780 (test_bitcoin+0x71e053)
    [#6](/bitcoin-bitcoin/6/) _M_invoke /usr/include/c++/7/bits/std_function.h:316 (test_bitcoin+0x71e677)
    [#7](/bitcoin-bitcoin/7/) std::function<void (std::unique_ptr<interfaces::Wallet, std::default_delete<interfaces::Wallet> >)>::operator()(std::unique_ptr<interfaces::Wallet, std::default_delete<interfaces::Wallet> >) const /usr/include/c++/7/bits/std_function.h:706 (test_bitcoin+0xd39850)
    [#8](/bitcoin-bitcoin/8/) CWallet::CreateWalletFromFile(interfaces::Chain&, WalletLocation const&, bilingual_str&, std::vector<bilingual_str, std::allocator<bilingual_str> >&, unsigned long) wallet/wallet.cpp:4006 (test_bitcoin+0xd39850)
    [#9](/bitcoin-bitcoin/9/) TestLoadWallet wallet/test/wallet_tests.cpp:37 (test_bitcoin+0x703587)
    [#10](/bitcoin-bitcoin/10/) wallet_tests::CreateWalletFromFile::test_method() wallet/test/wallet_tests.cpp:782 (test_bitcoin+0x72013e)
    [#11](/bitcoin-bitcoin/11/) CreateWalletFromFile_invoker wallet/test/wallet_tests.cpp:700 (test_bitcoin+0x721452)
    [#12](/bitcoin-bitcoin/12/) boost::detail::function::void_function_invoker0<void (*)(), void>::invoke(boost::detail::function::function_buffer&) /usr/include/boost/function/function_template.hpp:118 (test_bitcoin+0xe05fb)
    [#13](/bitcoin-bitcoin/13/) boost::detail::function::function_obj_invoker0<boost::detail::forward, int>::invoke(boost::detail::function::function_buffer&) <null> (libboost_unit_test_framework.so.1.65.1+0x4b2cd)
    [#14](/bitcoin-bitcoin/14/) __libc_start_main <null> (libc.so.6+0x21b96)

SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) (/usr/lib/x86_64-linux-gnu/libtsan.so.0+0x3fadb) in __interceptor_pthread_mutex_lock
==================
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found
WARNING: too long mutex cycle found

*** No errors detected
ThreadSanitizer: reported 1 warnings

The ThreadSanitizer does not report this issue on CI as the binaries are built with the --disable-wallet option: https://github.com/bitcoin/bitcoin/blob/df303ceb650521dc7b1ba91e0eea383c387a5860/ci/test/00_setup_env_native_tsan.sh#L14

UPDATE: This issue is caused by #16426 that has been merged on 2020-05-01.

I tried to debug this but it is very awkward because the mutexes are unnamed:

M134059 (0x7b6400004cc8) => M133094 (0x56527c390c60)

Is there some way we can provide tsan with better names than M134059 and M133094 for mutexes? Or alternately is it possible to find out from gdb if 0x7b6400004cc8 and 0x56527c390c60 correspond to symbols?

M134059 seems like it is the cs_wallets mutex since it is locked in wallet.cpp:4004

M133094 could be anything because second stack trace is useless and just shows some lock being acquired in some HandleLoadWallet callback. The HandleLoadWallet callback in the test is mining a new block, so maybe the mutex in question is cs_main or mempool.cs. But I don't see a case where cs_wallets would ever be locked while holding cs_main or cs_mempool. I do see cs_wallets is locked while holding cs_wallet in CreateWalletFromFile. So maybe M133094 is cs_wallet? cs_wallet is temporarily unlocked in HandleLoadWallet so I guess that technically could cause a deadlock if some other future nonexistent thread was added.

I guess feedback would here would be that I don't think tsan is doing anything useful for this test and should probably be suppressed. Also it would be good if it could display less confusing mutex names.

Is there some way we can provide tsan with better names than M134059 and M133094 for mutexes?

Looking at the clang source code - I think not :(

Or alternately is it possible to find out from gdb if 0x7b6400004cc8 and 0x56527c390c60 correspond to symbols?

(gdb) info symbol 0x7b6400004cc8 should be able to give some useful information, but for me it just prints No symbol matches 0x7fffffffd1b0 even though I have AnnotatedMixin<std::__1::mutex> object at that address. If you have a suspect you can inspect its address and see if it matches the address printed in the clang diagnostic.

Looking at the clang source code - I think not :(

Very interesting, thanks for looking into this!

The issue shouldn't be in any of our annotated mutexes right? Otherwise --enable-debug would detect the issue. Thus, at least one of the mutexes must be a mutex in bdb (or some other library).?

The issue shouldn't be in any of our annotated mutexes right? Otherwise --enable-debug would detect the issue. Thus, at least one of the mutexes must be a mutex in bdb (or some other library).?

Oh wow, that's a really good point. I think it strongly suggests the log mutex is involved, because it isn't annotated and this test relies a lot on log hooks. I think BDB probably isn't involved because there aren't really cases where BDB code would be calling back into our code while holding a mutex.

I think I might not be too concerned about debugging this issue right now because #15719 rewrites a lot the test and related code. But knowing that one of the mutexes probably isn't annotated definitely helps narrow the bug down.

It could also be a false-positive

The cycle is cs_wallet -> cs_wallets -> cs_wallet

TestLoadWallet here

https://github.com/bitcoin/bitcoin/blob/a1c0e5fce13911252a135bdce4ffc09c24d23791/src/wallet/test/wallet_tests.cpp#L771-L782

will call into CreateWalletFromFile, which locks walletInstance->cs_wallet and then cs_wallets:

https://github.com/bitcoin/bitcoin/blob/a1c0e5fce13911252a135bdce4ffc09c24d23791/src/wallet/wallet.cpp#L4020-L4027

However one of the handlers temporarily unlocks cs_wallet and thus creates a "hole" in the lock stack, which can lead to a deadlock (in theory, not in this test in practice of course).

And the reason that --enable-debug doesn't detect this is because it can't deal with "holes" (ripping out a lock from the lock stack).

@MarcoFalke

The cycle is cs_wallet -> cs_wallets -> cs_wallet

Is this a test design problem to be fixed?

I'm seeing another unreadable tsan error in this test here:

https://travis-ci.org/github/bitcoin/bitcoin/jobs/694884461

From the configure output, it seems like debug symbols (-g) are not enabled in the build. Is this an oversight or is there a reason debug symbols couldn't be enabled?

Is this a test design problem to be fixed?

I am not sure exactly which mutex gets locked when in this case, but any code that does "lock A, lock B, unlock A, lock A" is buggy and should be fixed (it locks B while holding A and later it locks A while holding B, so it could deadlock with another thread executing the same code).

From the configure output, it seems like debug symbols (-g) are not enabled in the build. Is this an oversight or is there a reason debug symbols couldn't be enabled?

--with-sanitizers=thread was introduced without -g and without --with-debug in 89bf196c8. -O2 could also screw up backtrace reports (inlining some functions and reorganizing the code, so that line numbers do not correspond to source code).

--- i/ci/test/00_setup_env_native_tsan.sh
+++ w/ci/test/00_setup_env_native_tsan.sh
@@ -8,7 +8,7 @@ export LC_ALL=C.UTF-8
 
 export CONTAINER_NAME=ci_native_tsan
 export DOCKER_NAME_TAG=ubuntu:20.04
 export PACKAGES="clang llvm libc++abi-dev libc++-dev python3-zmq"
 export DEP_OPTS="CC=clang CXX='clang++ -stdlib=libc++'"
 export GOAL="install"
-export BITCOIN_CONFIG="--enable-zmq --disable-wallet --with-gui=no CPPFLAGS='-DARENA_DEBUG -DDEBUG_LOCKORDER' --with-sanitizers=thread CC=clang CXX='clang++ -stdlib=libc++'"
+export BITCOIN_CONFIG="--enable-zmq --disable-wallet --with-gui=no --enable-debug --with-sanitizers=thread CPPFLAGS='-DARENA_DEBUG' CC=clang CXX='clang++ -stdlib=libc++'"

open PR, @MarcoFalke?

@vasild

-O2 could also screw up backtrace reports (inlining some functions and reorganizing the code, so that line numbers do not correspond to source code).

It seems https://clang.llvm.org/docs/ThreadSanitizer.html does not mention such behavior. Or did I miss something?

Well, that is just in general. It is not specific to TSan.

https://www.gnu.org/software/libc/manual/html_node/Backtraces.html mentions something about it:

Note that certain compiler optimizations may interfere with obtaining a valid backtrace. Function inlining causes the inlined function to not have a stack frame; tail call optimization replaces one stack frame with another; frame pointer elimination will stop backtrace from interpreting the stack contents correctly.

open PR, @MarcoFalke?

Sure as long as there is one build with DARENA_DEBUG

Is this a test design problem to be fixed?

I am not sure exactly which mutex gets locked when in this case, but any code that does "lock A, lock B, unlock A, lock A" is buggy and should be fixed (it locks B while holding A and later it locks A while holding B, so it could deadlock with another thread executing the same code).

For it to deadlock, there needs to be another thread not just executing the same code, but also using the same mutex instances. In a unit test, if the mutexes are per-test instance (not global variables), then there can't be a deadlock unless the test itself is written to have two or more of these threads running at the same time with the same mutexes. TSAN will complain, but there will not be any possibility of a deadlock if the test isn't creating multiple threads internally.

In this case, the cs_wallet mutex is unique to the test instance, and the other cs_wallets mutex is currently global, but #19101 updates it to be per-test instance.

--with-sanitizers=thread was introduced without -g and without --with-debug in 89bf196. -O2 could also screw up backtrace reports (inlining some functions and reorganizing the code, so that line numbers do not correspond to source code).

Thanks for finding that. To be sure, this only explains why the test is built without the other debug options, and there should be no problem adding -g? In any case I'll experiment with adding -g in the setup you pointed to and see if it helps makes TSAN output more readable.

I'm also confused about how the suppression file test/sanitizer_suppressions/tsan seems to be working with some mutex and variable names when tsan itself seems to not know these names

when tsan itself seems to not know these names

The llvm symbolizer is required to translate symbol addresses to names. Is that what you mean?

Btw, this unit test in now in the suppressions file:

https://github.com/bitcoin/bitcoin/blob/aa35ea55021dbb7f35a00fd666903d9fd03b88e7/test/sanitizer_suppressions/tsan#L30

when tsan itself seems to not know these names

The llvm symbolizer is required to translate symbol addresses to names. Is that what you mean?

I just mean that TSAN output contains "Mutex M262581 (0x7b3800000670) created at:" "Mutex M129 (0x55a6939ca390)" "Mutex M135 (0x55a6939ca578) created at" "https://travis-ci.org/github/bitcoin/bitcoin/jobs/694884461" without readable names. If the tsan error printer doesn't know the real mutex names, why would the tsan error suppressor know the mutex names?

re: me #19049 (comment)

In any case I'll experiment with adding -g in the setup you pointed to and see if it helps makes TSAN output more readable.

Seems like with -g, there are line numbers, but still no mutex names:

https://travis-ci.org/github/bitcoin/bitcoin/jobs/694884461 (without -g) https://travis-ci.org/github/bitcoin/bitcoin/jobs/695004018 (with -g)

Note for myself: the warning is silenced in #19164.