Merge #19982: test: Fix inconsistent lock order in wallet_tests/CreateWallet

e1e68b6305 test: Fix inconsistent lock order in wallet_tests/CreateWallet (Hennadii Stepanov)
cb23fe01c1 [skip ci] sync: Check precondition in LEAVE_CRITICAL_SECTION() macro (Hennadii Stepanov)
c5e3e74f70 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:
  b99a1633b2/src/rpc/mining.cpp (L698)

  b99a1633b2/src/checkqueue.h (L208)

ACKs for top commit:
  MarcoFalke:
    review ACK e1e68b6305 💂
  ryanofsky:
    Code review ACK e1e68b6305. Just trivial rebase and suggested switch to BOOST_CHECK_EXCEPTION since last review
  vasild:
    ACK e1e68b630

Tree-SHA512: a627680eac3af4b4c02772473d68322ce8d3811bf6b035d3485ccc97d35755bef933cffabd3f20b126f89e3301eccecec3f769df34415fb7c426c967b6ce36e6

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<std::mutex> lock(lockdata.dd_mutex);
+    LockData& lockdata = GetLockData();
+    std::lock_guard<std::mutex> 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()

src/sync.h

@@ -242,10 +242,12 @@ using DebugLock = UniqueLock<typename std::remove_reference<typename std::remove
         (cs).lock();                                          \
     }
 
-#define LEAVE_CRITICAL_SECTION(cs) \
-    {                              \
-        (cs).unlock();             \
-        LeaveCritical();           \
+#define LEAVE_CRITICAL_SECTION(cs)                                          \
+    {                                                                       \
+        std::string lockname;                                               \
+        CheckLastCritical((void*)(&cs), lockname, #cs, __FILE__, __LINE__); \
+        (cs).unlock();                                                      \
+        LeaveCritical();                                                    \
     }
 
 //! Run code while locking a mutex.

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

src/test/sync_tests.cpp

@@ -62,6 +62,19 @@ void TestDoubleLock(bool should_throw)
     g_debug_lockorder_abort = prev;
 }
 #endif /* DEBUG_LOCKORDER */
+
+template <typename MutexType>
+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()

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<interfaces::Wallet> wallet) EXCLUSIVE_LOCKS_REQUIRED(wallet->wallet()->cs_wallet) {
+    auto handler = HandleLoadWallet([&](std::unique_ptr<interfaces::Wallet> 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);

src/wallet/wallet.cpp

@@ -52,7 +52,7 @@ const std::map<uint64_t,std::string> WALLET_FLAG_CAVEATS{
 
 static const size_t OUTPUT_GROUP_MAX_ENTRIES = 10;
 
-static RecursiveMutex cs_wallets;
+RecursiveMutex cs_wallets;
 static std::vector<std::shared_ptr<CWallet>> vpwallets GUARDED_BY(cs_wallets);
 static std::list<LoadWalletFn> g_load_wallet_fns GUARDED_BY(cs_wallets);
 

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