From 25bdc2670eda53e667d7b3e4fedd8fa1d4c9b147 Mon Sep 17 00:00:00 2001 From: fanquake Date: Fri, 11 Dec 2020 08:54:57 +0800 Subject: [PATCH] Merge #19982: test: Fix inconsistent lock order in wallet_tests/CreateWallet MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit e1e68b6305beb47ebf7ee48f14e12fdebdfea1ef test: Fix inconsistent lock order in wallet_tests/CreateWallet (Hennadii Stepanov) cb23fe01c125e1820f3c37348e06d98c93e6aec2 sync: Check precondition in LEAVE_CRITICAL_SECTION() macro (Hennadii Stepanov) c5e3e74f70c29ac8852903ef425f5f327d5da969 sync: Improve CheckLastCritical() (Hennadii Stepanov) Pull request description: This PR: - fixes #19049 that was caused by #16426 - removes `wallet_tests::CreateWallet` suppression from the `test/sanitizer_suppressions/tsan` The example of the improved `CheckLastCritical()`/`LEAVE_CRITICAL_SECTION()` log (could be got when compiled without the last commit): ``` 2020-09-20T08:34:28.429485Z [test] INCONSISTENT LOCK ORDER DETECTED 2020-09-20T08:34:28.429493Z [test] Current lock order (least recent first) is: 2020-09-20T08:34:28.429501Z [test] 'walletInstance->cs_wallet' in wallet/wallet.cpp:4007 (in thread 'test') 2020-09-20T08:34:28.429508Z [test] 'cs_wallets' in wallet/wallet.cpp:4089 (in thread 'test') ``` Currently, there are other "naked" `LEAVE_CRITICAL_SECTION()` in the code base: https://github.com/bitcoin/bitcoin/blob/b99a1633b270e0e89479b2bb2ae19a8a8dc0fa05/src/rpc/mining.cpp#L698 https://github.com/bitcoin/bitcoin/blob/b99a1633b270e0e89479b2bb2ae19a8a8dc0fa05/src/checkqueue.h#L208 ACKs for top commit: MarcoFalke: review ACK e1e68b6305beb47ebf7ee48f14e12fdebdfea1ef 💂 ryanofsky: Code review ACK e1e68b6305beb47ebf7ee48f14e12fdebdfea1ef. Just trivial rebase and suggested switch to BOOST_CHECK_EXCEPTION since last review vasild: ACK e1e68b630 Tree-SHA512: a627680eac3af4b4c02772473d68322ce8d3811bf6b035d3485ccc97d35755bef933cffabd3f20b126f89e3301eccecec3f769df34415fb7c426c967b6ce36e6 --- src/sync.cpp | 32 ++++++++++++++++----------- src/sync.h | 10 +++++---- src/test/reverselock_tests.cpp | 10 +++++---- src/test/sync_tests.cpp | 37 ++++++++++++++++++++++++++++++++ src/wallet/test/wallet_tests.cpp | 6 +++++- src/wallet/wallet.cpp | 2 +- 6 files changed, 75 insertions(+), 22 deletions(-) diff --git a/src/sync.cpp b/src/sync.cpp index c55086bcdc39c..ae05eebbe92b9 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -186,20 +186,28 @@ void EnterCritical(const char* pszName, const char* pszFile, int nLine, void* cs 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); - - 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; - } + 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; } } - 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/sync.h b/src/sync.h index be707c48b871e..880ce460ca363 100644 --- a/src/sync.h +++ b/src/sync.h @@ -239,10 +239,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) @@ -55,4 +68,28 @@ BOOST_AUTO_TEST_CASE(potential_deadlock_detected) #endif } +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() diff --git a/src/wallet/test/wallet_tests.cpp b/src/wallet/test/wallet_tests.cpp index 5061583a47b17..6626347f0a1f6 100644 --- a/src/wallet/test/wallet_tests.cpp +++ b/src/wallet/test/wallet_tests.cpp @@ -34,6 +34,8 @@ extern UniValue getrawchangeaddress(const JSONRPCRequest& request); extern UniValue getaddressinfo(const JSONRPCRequest& request); extern UniValue addmultisigaddress(const JSONRPCRequest& request); +extern RecursiveMutex cs_wallets; + BOOST_FIXTURE_TEST_SUITE(wallet_tests, WalletTestingSetup) static std::shared_ptr TestLoadWallet(interfaces::Chain& chain) @@ -1300,16 +1302,18 @@ BOOST_FIXTURE_TEST_CASE(CreateWalletFromFile, 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(chain->broadcastTransaction(MakeTransactionRef(mempool_tx), error, DEFAULT_TRANSACTION_MAXFEE, false)); + 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(*chain); BOOST_CHECK_EQUAL(addtx_count, 4); diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index 8c22bb824ae0b..4005b51b60e48 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -67,7 +67,7 @@ const std::map WALLET_FLAG_CAVEATS{ static const size_t OUTPUT_GROUP_MAX_ENTRIES = 10; -static CCriticalSection cs_wallets; +CCriticalSection cs_wallets; static std::vector> vpwallets GUARDED_BY(cs_wallets); static std::list g_load_wallet_fns GUARDED_BY(cs_wallets);