test: make it possible for DebugLogHelper to wait for messages

Extend `DebugLogHelper::~DebugLogHelper()` to be able to
optionally wait for messages, possibly logged from another thread, to
arrive before performing the final check.

src/test/util/logging.cpp

@@ -12,20 +12,31 @@
 #include <iostream>
 #include <stdexcept>
 
-DebugLogHelper::DebugLogHelper(std::string message, MatchFn match)
-    : m_message{std::move(message)}, m_match(std::move(match))
+DebugLogHelper::DebugLogHelper(std::string message, MatchFn match, std::optional<std::chrono::milliseconds> timeout)
+    : m_message{std::move(message)}, m_timeout{timeout}, m_match(std::move(match))
 {
     m_print_connection = LogInstance().PushBackCallback(
         [this](const std::string& s) {
-            if (m_found) return;
-            m_found = s.find(m_message) != std::string::npos && m_match(&s);
+            StdLockGuard lock{m_mutex};
+            if (!m_found) {
+                if (s.find(m_message) != std::string::npos && m_match(&s)) {
+                    m_found = true;
+                    m_cv.notify_all();
+                }
+            }
         });
     noui_test_redirect();
     m_receiving_log = true;
 }
 
 DebugLogHelper::~DebugLogHelper()
 {
+    {
+        StdUniqueLock lock{m_mutex};
+        if (m_timeout.has_value()) {
+            m_cv.wait_for(lock, m_timeout.value(), [this]() EXCLUSIVE_LOCKS_REQUIRED(m_mutex) { return m_found; });
+        }
+    }
     StopReceivingLog();
     if (!m_found && m_match(nullptr)) {
         std::cerr << "Fatal error: expected message not found in the debug log: " << m_message << "\n";

src/test/util/logging.h

@@ -5,24 +5,42 @@
 #ifndef BITCOIN_TEST_UTIL_LOGGING_H
 #define BITCOIN_TEST_UTIL_LOGGING_H
 
+#include <sync.h>
 #include <util/macros.h>
 
+#include <chrono>
+#include <condition_variable>
 #include <functional>
 #include <list>
+#include <optional>
 #include <string>
 
 class DebugLogHelper
 {
 public:
     using MatchFn = std::function<bool(const std::string* line)>;
 
-    explicit DebugLogHelper(std::string message, MatchFn match = [](const std::string*){ return true; });
+    static bool MatchFnDefault(const std::string*)
+    {
+        return true;
+    }
+
+    explicit DebugLogHelper(
+        std::string message,
+        MatchFn match = MatchFnDefault,
+        std::optional<std::chrono::milliseconds> timeout = std::nullopt);
 
     ~DebugLogHelper();
 
 private:
     const std::string m_message;
-    bool m_found{false};
+    const std::optional<std::chrono::milliseconds> m_timeout;
+    // Mutex + LOCK() is not usable here because LOCK() may print to the log
+    // itself (see DEBUG_LOCKCONTENTION) causing a deadlock between this mutex
+    // and BCLog::Logger::m_cs which is acquired when logging a message.
+    StdMutex m_mutex;
+    std::condition_variable_any m_cv;
+    bool m_found GUARDED_BY(m_mutex){false};
     std::list<std::function<void(const std::string&)>>::iterator m_print_connection;
 
     //! Custom match checking function.
@@ -42,4 +60,7 @@ class DebugLogHelper
 
 #define ASSERT_DEBUG_LOG(message) DebugLogHelper UNIQUE_NAME(debugloghelper)(message)
 
+#define ASSERT_DEBUG_LOG_WAIT(message, timeout) \
+    DebugLogHelper UNIQUE_NAME(debugloghelper)(message, DebugLogHelper::MatchFnDefault, timeout)
+
 #endif // BITCOIN_TEST_UTIL_LOGGING_H

src/threadsafety.h

@@ -74,4 +74,13 @@ class SCOPED_LOCKABLE StdLockGuard : public std::lock_guard<StdMutex>
     ~StdLockGuard() UNLOCK_FUNCTION() = default;
 };
 
+// StdUniqueLock provides an annotated version of std::unique_lock for us,
+// and should only be used when sync.h Mutex/LOCK/etc are not usable.
+class SCOPED_LOCKABLE StdUniqueLock : public std::unique_lock<StdMutex>
+{
+public:
+    explicit StdUniqueLock(StdMutex& cs) EXCLUSIVE_LOCK_FUNCTION(cs) : std::unique_lock<StdMutex>(cs) {}
+    ~StdUniqueLock() UNLOCK_FUNCTION() {}
+};
+
 #endif // BITCOIN_THREADSAFETY_H