From c5e3e74f70c29ac8852903ef425f5f327d5da969 Mon Sep 17 00:00:00 2001 From: Hennadii Stepanov <32963518+hebasto@users.noreply.github.com> Date: Sun, 20 Sep 2020 11:33:48 +0300 Subject: [PATCH 1/3] sync: Improve CheckLastCritical() This commit adds actual lock stack logging if check fails. --- src/sync.cpp | 30 +++++++++++++++++++----------- src/test/reverselock_tests.cpp | 10 ++++++---- 2 files changed, 25 insertions(+), 15 deletions(-) diff --git a/src/sync.cpp b/src/sync.cpp index f07916041ab..acfbe8fe29b 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -228,20 +228,28 @@ template void EnterCritical(const char*, const char*, int, boost::mutex*, bool); void CheckLastCritical(void* cs, std::string& lockname, const char* guardname, const char* file, int line) { - { - LockData& lockdata = GetLockData(); - std::lock_guard lock(lockdata.dd_mutex); + LockData& lockdata = GetLockData(); + std::lock_guard lock(lockdata.dd_mutex); - const LockStack& lock_stack = lockdata.m_lock_stacks[std::this_thread::get_id()]; - if (!lock_stack.empty()) { - const auto& lastlock = lock_stack.back(); - if (lastlock.first == cs) { - lockname = lastlock.second.Name(); - return; - } + const LockStack& lock_stack = lockdata.m_lock_stacks[std::this_thread::get_id()]; + if (!lock_stack.empty()) { + const auto& lastlock = lock_stack.back(); + if (lastlock.first == cs) { + lockname = lastlock.second.Name(); + return; } } - throw std::system_error(EPERM, std::generic_category(), strprintf("%s:%s %s was not most recent critical section locked", file, line, guardname)); + + LogPrintf("INCONSISTENT LOCK ORDER DETECTED\n"); + LogPrintf("Current lock order (least recent first) is:\n"); + for (const LockStackItem& i : lock_stack) { + LogPrintf(" %s\n", i.second.ToString()); + } + if (g_debug_lockorder_abort) { + tfm::format(std::cerr, "%s:%s %s was not most recent critical section locked, details in debug log.\n", file, line, guardname); + abort(); + } + throw std::logic_error(strprintf("%s was not most recent critical section locked", guardname)); } void LeaveCritical() diff --git a/src/test/reverselock_tests.cpp b/src/test/reverselock_tests.cpp index a42608a66d8..7da364d316e 100644 --- a/src/test/reverselock_tests.cpp +++ b/src/test/reverselock_tests.cpp @@ -48,12 +48,14 @@ BOOST_AUTO_TEST_CASE(reverselock_errors) WAIT_LOCK(mutex, lock); #ifdef DEBUG_LOCKORDER + bool prev = g_debug_lockorder_abort; + g_debug_lockorder_abort = false; + // Make sure trying to reverse lock a previous lock fails - try { - REVERSE_LOCK(lock2); - BOOST_CHECK(false); // REVERSE_LOCK(lock2) succeeded - } catch(...) { } + BOOST_CHECK_EXCEPTION(REVERSE_LOCK(lock2), std::logic_error, HasReason("lock2 was not most recent critical section locked")); BOOST_CHECK(lock2.owns_lock()); + + g_debug_lockorder_abort = prev; #endif // Make sure trying to reverse lock an unlocked lock fails From cb23fe01c125e1820f3c37348e06d98c93e6aec2 Mon Sep 17 00:00:00 2001 From: Hennadii Stepanov <32963518+hebasto@users.noreply.github.com> Date: Sun, 20 Sep 2020 11:38:03 +0300 Subject: [PATCH 2/3] [skip ci] sync: Check precondition in LEAVE_CRITICAL_SECTION() macro This change reveals a bug in the wallet_tests/CreateWalletFromFile test, that will be fixed in the following commit. --- src/sync.h | 10 ++++++---- src/test/sync_tests.cpp | 37 +++++++++++++++++++++++++++++++++++++ 2 files changed, 43 insertions(+), 4 deletions(-) diff --git a/src/sync.h b/src/sync.h index 0948083c7f0..749bf5575c4 100644 --- a/src/sync.h +++ b/src/sync.h @@ -242,10 +242,12 @@ using DebugLock = UniqueLock +void TestInconsistentLockOrderDetected(MutexType& mutex1, MutexType& mutex2) NO_THREAD_SAFETY_ANALYSIS +{ + ENTER_CRITICAL_SECTION(mutex1); + ENTER_CRITICAL_SECTION(mutex2); +#ifdef DEBUG_LOCKORDER + BOOST_CHECK_EXCEPTION(LEAVE_CRITICAL_SECTION(mutex1), std::logic_error, HasReason("mutex1 was not most recent critical section locked")); +#endif // DEBUG_LOCKORDER + LEAVE_CRITICAL_SECTION(mutex2); + LEAVE_CRITICAL_SECTION(mutex1); + BOOST_CHECK(LockStackEmpty()); +} } // namespace BOOST_FIXTURE_TEST_SUITE(sync_tests, BasicTestingSetup) @@ -108,4 +121,28 @@ BOOST_AUTO_TEST_CASE(double_lock_recursive_mutex) } #endif /* DEBUG_LOCKORDER */ +BOOST_AUTO_TEST_CASE(inconsistent_lock_order_detected) +{ +#ifdef DEBUG_LOCKORDER + bool prev = g_debug_lockorder_abort; + g_debug_lockorder_abort = false; +#endif // DEBUG_LOCKORDER + + RecursiveMutex rmutex1, rmutex2; + TestInconsistentLockOrderDetected(rmutex1, rmutex2); + // By checking lock order consistency (CheckLastCritical) before any unlocking (LeaveCritical) + // the lock tracking data must not have been broken by exception. + TestInconsistentLockOrderDetected(rmutex1, rmutex2); + + Mutex mutex1, mutex2; + TestInconsistentLockOrderDetected(mutex1, mutex2); + // By checking lock order consistency (CheckLastCritical) before any unlocking (LeaveCritical) + // the lock tracking data must not have been broken by exception. + TestInconsistentLockOrderDetected(mutex1, mutex2); + +#ifdef DEBUG_LOCKORDER + g_debug_lockorder_abort = prev; +#endif // DEBUG_LOCKORDER +} + BOOST_AUTO_TEST_SUITE_END() From e1e68b6305beb47ebf7ee48f14e12fdebdfea1ef Mon Sep 17 00:00:00 2001 From: Hennadii Stepanov <32963518+hebasto@users.noreply.github.com> Date: Sun, 20 Sep 2020 11:54:58 +0300 Subject: [PATCH 3/3] test: Fix inconsistent lock order in wallet_tests/CreateWallet --- src/wallet/test/wallet_tests.cpp | 6 +++++- src/wallet/wallet.cpp | 2 +- test/sanitizer_suppressions/tsan | 1 - 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/src/wallet/test/wallet_tests.cpp b/src/wallet/test/wallet_tests.cpp index eb0bbb6ccca..a6db2619140 100644 --- a/src/wallet/test/wallet_tests.cpp +++ b/src/wallet/test/wallet_tests.cpp @@ -28,6 +28,8 @@ RPCHelpMan importmulti(); RPCHelpMan dumpwallet(); RPCHelpMan importwallet(); +extern RecursiveMutex cs_wallets; + // Ensure that fee levels defined in the wallet are at least as high // as the default levels for node policy. static_assert(DEFAULT_TRANSACTION_MINFEE >= DEFAULT_MIN_RELAY_TX_FEE, "wallet minimum fee is smaller than default relay fee"); @@ -761,16 +763,18 @@ BOOST_FIXTURE_TEST_CASE(CreateWallet, TestChain100Setup) // deadlock during the sync and simulates a new block notification happening // as soon as possible. addtx_count = 0; - auto handler = HandleLoadWallet([&](std::unique_ptr wallet) EXCLUSIVE_LOCKS_REQUIRED(wallet->wallet()->cs_wallet) { + auto handler = HandleLoadWallet([&](std::unique_ptr wallet) EXCLUSIVE_LOCKS_REQUIRED(wallet->wallet()->cs_wallet, cs_wallets) { BOOST_CHECK(rescan_completed); m_coinbase_txns.push_back(CreateAndProcessBlock({}, GetScriptForRawPubKey(coinbaseKey.GetPubKey())).vtx[0]); block_tx = TestSimpleSpend(*m_coinbase_txns[2], 0, coinbaseKey, GetScriptForRawPubKey(key.GetPubKey())); m_coinbase_txns.push_back(CreateAndProcessBlock({block_tx}, GetScriptForRawPubKey(coinbaseKey.GetPubKey())).vtx[0]); mempool_tx = TestSimpleSpend(*m_coinbase_txns[3], 0, coinbaseKey, GetScriptForRawPubKey(key.GetPubKey())); BOOST_CHECK(m_node.chain->broadcastTransaction(MakeTransactionRef(mempool_tx), DEFAULT_TRANSACTION_MAXFEE, false, error)); + LEAVE_CRITICAL_SECTION(cs_wallets); LEAVE_CRITICAL_SECTION(wallet->wallet()->cs_wallet); SyncWithValidationInterfaceQueue(); ENTER_CRITICAL_SECTION(wallet->wallet()->cs_wallet); + ENTER_CRITICAL_SECTION(cs_wallets); }); wallet = TestLoadWallet(*m_node.chain); BOOST_CHECK_EQUAL(addtx_count, 4); diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index 8350d66fa74..01bda27d57c 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -52,7 +52,7 @@ const std::map WALLET_FLAG_CAVEATS{ static const size_t OUTPUT_GROUP_MAX_ENTRIES = 10; -static RecursiveMutex cs_wallets; +RecursiveMutex cs_wallets; static std::vector> vpwallets GUARDED_BY(cs_wallets); static std::list g_load_wallet_fns GUARDED_BY(cs_wallets); diff --git a/test/sanitizer_suppressions/tsan b/test/sanitizer_suppressions/tsan index 48f81f3dbfd..986e096056b 100644 --- a/test/sanitizer_suppressions/tsan +++ b/test/sanitizer_suppressions/tsan @@ -32,7 +32,6 @@ deadlock:CConnman::ForNode deadlock:CConnman::GetNodeStats deadlock:CChainState::ConnectTip deadlock:UpdateTip -deadlock:wallet_tests::CreateWallet # WalletBatch (unidentified deadlock) deadlock:WalletBatch