test: Fix inconsistent lock order in wallet_tests/CreateWallet

Summary:
> sync: Improve CheckLastCritical()
>
> This commit adds actual lock stack logging if check fails.

> [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.

> test: Fix inconsistent lock order in wallet_tests/CreateWallet

This is a backport of [[bitcoin/bitcoin#19982 | core#19982]]

Test Plan:
I confirmed that after commit #2, running `ninja check` with  `-DCMAKE_BUILD_TYPE=Debug`  reveals a lock order issue:
```
../src/wallet/test/wallet_tests.cpp:853 wallet_param->wallet()->cs_wallet was not most recent critical section locked, details in debug log.
```

This goes away with the next commit.

Tested also with TSAN, after removing the suppression.

Reviewers: #bitcoin_abc, Fabien

Reviewed By: #bitcoin_abc, Fabien

Differential Revision: https://reviews.bitcoinabc.org/D11093

Author: hebasto

src/sync.cpp

@@ -176,24 +176,33 @@ void EnterCritical(const char *pszName, const char *pszFile, int nLine,
 
 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);
-
-        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<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;
         }
     }
-    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

@@ -257,6 +257,8 @@ using DebugLock = UniqueLock<typename std::remove_reference<
 
 #define LEAVE_CRITICAL_SECTION(cs)                                             \
     {                                                                          \
+        std::string lockname;                                                  \
+        CheckLastCritical((void *)(&cs), lockname, #cs, __FILE__, __LINE__);   \
         (cs).unlock();                                                         \
         LeaveCritical();                                                       \
     }

src/test/reverselock_tests.cpp

@@ -46,13 +46,16 @@ 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

@@ -28,6 +28,21 @@ void TestPotentialDeadLockDetected(MutexType &mutex1, MutexType &mutex2) {
     BOOST_CHECK(!error_thrown);
 #endif
 }
+
+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)
@@ -55,4 +70,29 @@ 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()

src/wallet/test/wallet_tests.cpp

@@ -29,6 +29,8 @@
 #include <memory>
 #include <vector>
 
+extern RecursiveMutex cs_wallets;
+
 BOOST_FIXTURE_TEST_SUITE(wallet_tests, WalletTestingSetup)
 
 static std::shared_ptr<CWallet> TestLoadWallet(interfaces::Chain &chain) {
@@ -830,7 +832,8 @@ BOOST_FIXTURE_TEST_CASE(CreateWallet, TestChain100Setup) {
     addtx_count = 0;
     auto handler = HandleLoadWallet(
         [&](std::unique_ptr<interfaces::Wallet> wallet_param)
-            EXCLUSIVE_LOCKS_REQUIRED(wallet_param->wallet()->cs_wallet) {
+            EXCLUSIVE_LOCKS_REQUIRED(wallet_param->wallet()->cs_wallet,
+                                     cs_wallets) {
                 BOOST_CHECK(rescan_completed);
                 m_coinbase_txns.push_back(
                     CreateAndProcessBlock(
@@ -850,9 +853,11 @@ BOOST_FIXTURE_TEST_CASE(CreateWallet, TestChain100Setup) {
                 BOOST_CHECK(chain->broadcastTransaction(
                     GetConfig(), MakeTransactionRef(mempool_tx),
                     DEFAULT_TRANSACTION_MAXFEE, false, error));
+                LEAVE_CRITICAL_SECTION(cs_wallets);
                 LEAVE_CRITICAL_SECTION(wallet_param->wallet()->cs_wallet);
                 SyncWithValidationInterfaceQueue();
                 ENTER_CRITICAL_SECTION(wallet_param->wallet()->cs_wallet);
+                ENTER_CRITICAL_SECTION(cs_wallets);
             });
     wallet = TestLoadWallet(*chain);
     BOOST_CHECK_EQUAL(addtx_count, 4);

src/wallet/wallet.cpp

@@ -45,7 +45,7 @@ const std::map<uint64_t, std::string> WALLET_FLAG_CAVEATS{
      "be considered unused, even if the opposite is the case."},
 };
 
-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

@@ -35,7 +35,6 @@ deadlock:CConnman::ForNode
 deadlock:CConnman::GetNodeStats
 deadlock:CChainState::ConnectTip
 deadlock:UpdateTip
-deadlock:wallet_tests::CreateWallet
 
 # Lock order inversion due to the large cs_main lock from Shutdown, which comes
 # before the cs_proofrequest lock