Merge bitcoin#19353: Fix mistakenly swapped "previous" and "current" lock orders

0ecff9d Improve "detected inconsistent lock order" error message (Hennadii Stepanov)
bbe9cf4 test: Improve "potential deadlock detected" exception message (Hennadii Stepanov)
3559934 Fix mistakenly swapped "previous" and "current" lock orders (Hennadii Stepanov)

Pull request description:

  In master (8ef15e8) the "previous" and "current" lock orders are mistakenly swapped.

  This PR:
  - fixes printed lock orders
  - improves the `sync_tests` unit test
  - makes the "detected inconsistent lock order" error message pointing to the lock location rather `tfm::format()` location.

  Debugger output example with this PR (with modified code, of course):
  ```
  2020-06-22T15:46:56Z [msghand] POTENTIAL DEADLOCK DETECTED
  2020-06-22T15:46:56Z [msghand] Previous lock order was:
  2020-06-22T15:46:56Z [msghand]  (2) 'cs_main' in net_processing.cpp:2545 (in thread 'msghand')
  2020-06-22T15:46:56Z [msghand]  (1) 'g_cs_orphans' in net_processing.cpp:1400 (in thread 'msghand')
  2020-06-22T15:46:56Z [msghand] Current lock order is:
  2020-06-22T15:46:56Z [msghand]  (1) 'g_cs_orphans' in net_processing.cpp:2816 (in thread 'msghand')
  2020-06-22T15:46:56Z [msghand]  (2) 'cs_main' in net_processing.cpp:2816 (in thread 'msghand')
  Assertion failed: detected inconsistent lock order for 'cs_main' in net_processing.cpp:2816 (in thread 'msghand'), details in debug log.
  Process 131393 stopped
  * thread bitcoin#15, name = 'b-msghand', stop reason = signal SIGABRT
      frame #0: 0x00007ffff775c18b libc.so.6`__GI_raise(sig=2) at raise.c:51:1
  (lldb) bt
  * thread bitcoin#15, name = 'b-msghand', stop reason = signal SIGABRT
    * frame #0: 0x00007ffff775c18b libc.so.6`__GI_raise(sig=2) at raise.c:51:1
      frame #1: 0x00007ffff773b859 libc.so.6`__GI_abort at abort.c:79:7
      frame #2: 0x0000555555e5b196 bitcoind`(anonymous namespace)::potential_deadlock_detected(mismatch=0x00007fff99ff6f30, s1=size=2, s2=size=2, lock_location=0x00007fff99ff7010) at sync.cpp:134:9
      frame #3: 0x0000555555e5a1b1 bitcoind`(anonymous namespace)::push_lock(c=0x0000555556379220, locklocation=0x00007fff99ff7010) at sync.cpp:158:13
      frame #4: 0x0000555555e59e8a bitcoind`EnterCritical(pszName="cs_main", pszFile="net_processing.cpp", nLine=2816, cs=0x0000555556379220, fTry=false) at sync.cpp:177:5
      frame #5: 0x00005555555b0500 bitcoind`UniqueLock<AnnotatedMixin<std::recursive_mutex>, std::unique_lock<std::recursive_mutex> >::Enter(this=0x00007fff99ff8c20, pszName="cs_main", pszFile="net_processing.cpp", nLine=2816) at sync.h:134:9
      frame #6: 0x00005555555b017f bitcoind`UniqueLock<AnnotatedMixin<std::recursive_mutex>, std::unique_lock<std::recursive_mutex> >::UniqueLock(this=0x00007fff99ff8c20, mutexIn=0x0000555556379220, pszName="cs_main", pszFile="net_processing.cpp", nLine=2816, fTry=false) at sync.h:160:13
      frame #7: 0x00005555556aa57e bitcoind`ProcessMessage(pfrom=0x00007fff90001180, msg_type=error: summary string parsing error, vRecv=0x00007fff9c005ac0, nTimeReceived=1592840815980751, chainparams=0x00005555564b7110, chainman=0x0000555556380880, mempool=0x0000555556380ae0, connman=0x000055555657aa20, banman=0x00005555565167b0, interruptMsgProc=0x00005555565cae90) at net_processing.cpp:2816:9
  ```

ACKs for top commit:
  laanwj:
    ACK 0ecff9d
  vasild:
    ACK 0ecff9d

Tree-SHA512: ff285de8dd3198b5b33c4bfbdadf9b1448189c96143b9696bc4f41c07e784c00851ec169cf3ed45cc325f3617ba6783620803234f57fcce28bf6bc3d6a7234fb

Author: laanwj

src/sync.cpp

@@ -60,7 +60,7 @@ struct CLockLocation {
     std::string ToString() const
     {
         return strprintf(
-            "%s %s:%s%s (in thread %s)",
+            "'%s' in %s:%s%s (in thread '%s')",
             mutexName, sourceFile, sourceLine, (fTry ? " (TRY)" : ""), m_thread_name);
     }
 
@@ -105,7 +105,7 @@ static void potential_deadlock_detected(const LockPair& mismatch, const LockStac
 {
     LogPrintf("POTENTIAL DEADLOCK DETECTED\n");
     LogPrintf("Previous lock order was:\n");
-    for (const LockStackItem& i : s2) {
+    for (const LockStackItem& i : s1) {
         if (i.first == mismatch.first) {
             LogPrintf(" (1)"); /* Continued */
         }
@@ -114,21 +114,25 @@ static void potential_deadlock_detected(const LockPair& mismatch, const LockStac
         }
         LogPrintf(" %s\n", i.second.ToString());
     }
+
+    std::string mutex_a, mutex_b;
     LogPrintf("Current lock order is:\n");
-    for (const LockStackItem& i : s1) {
+    for (const LockStackItem& i : s2) {
         if (i.first == mismatch.first) {
             LogPrintf(" (1)"); /* Continued */
+            mutex_a = i.second.Name();
         }
         if (i.first == mismatch.second) {
             LogPrintf(" (2)"); /* Continued */
+            mutex_b = i.second.Name();
         }
         LogPrintf(" %s\n", i.second.ToString());
     }
     if (g_debug_lockorder_abort) {
-        tfm::format(std::cerr, "Assertion failed: detected inconsistent lock order at %s:%i, details in debug log.\n", __FILE__, __LINE__);
+        tfm::format(std::cerr, "Assertion failed: detected inconsistent lock order for %s, details in debug log.\n", s2.back().second.ToString());
         abort();
     }
-    throw std::logic_error("potential deadlock detected");
+    throw std::logic_error(strprintf("potential deadlock detected: %s -> %s -> %s", mutex_b, mutex_a, mutex_b));
 }
 
 static void push_lock(void* c, const CLockLocation& locklocation)

src/test/sync_tests.cpp

@@ -18,7 +18,7 @@ void TestPotentialDeadLockDetected(MutexType& mutex1, MutexType& mutex2)
     try {
         LOCK2(mutex2, mutex1);
     } catch (const std::logic_error& e) {
-        BOOST_CHECK_EQUAL(e.what(), "potential deadlock detected");
+        BOOST_CHECK_EQUAL(e.what(), "potential deadlock detected: mutex1 -> mutex2 -> mutex1");
         error_thrown = true;
     }
     #ifdef DEBUG_LOCKORDER