From a0642a894e63b4bc28305ec3d9f7fa58887c3312 Mon Sep 17 00:00:00 2001
From: Jason Rhinelander <jason@imaginary.ca>
Date: Wed, 23 Jun 2021 10:55:47 -0300
Subject: [PATCH] Miscellaneous small test suite fixes/improvements

- Allow up to 200ms (instead of 100ms) for the things we are waiting on
to become available, to prevent occasional spurious failures.
- Add unscoped info for how long we waited.
- Avoid calling into oxenmq with the catch lock held in the "hey google"
tests (because this will deadlock if the oxenmq call invokes any
logging).
- Replace an old std::cerr logger with the updated catch2 logger.
---
 tests/common.h          | 20 ++++++++++++--------
 tests/test_commands.cpp | 32 ++++++++++++++++++++------------
 2 files changed, 32 insertions(+), 20 deletions(-)

diff --git a/tests/common.h b/tests/common.h
index 6dda8f6..2798675 100644
--- a/tests/common.h
+++ b/tests/common.h
@@ -1,6 +1,7 @@
 #pragma once
 #include "oxenmq/oxenmq.h"
 #include <catch2/catch.hpp>
+#include <chrono>
 
 using namespace oxenmq;
 
@@ -16,14 +17,23 @@ inline std::string random_localhost() {
 }
 
 
-/// Waits up to 100ms for something to happen.
+// Catch2 macros aren't thread safe, so guard with a mutex
+inline std::unique_lock<std::mutex> catch_lock() {
+    static std::mutex mutex;
+    return std::unique_lock<std::mutex>{mutex};
+}
+
+/// Waits up to 200ms for something to happen.
 template <typename Func>
 inline void wait_for(Func f) {
-    for (int i = 0; i < 10; i++) {
+    auto start = std::chrono::steady_clock::now();
+    for (int i = 0; i < 20; i++) {
         if (f())
             break;
         std::this_thread::sleep_for(10ms);
     }
+    auto lock = catch_lock();
+    UNSCOPED_INFO("done waiting after " << (std::chrono::steady_clock::now() - start).count() << "ns");
 }
 
 /// Waits on an atomic bool for up to 100ms for an initial connection, which is more than enough
@@ -35,12 +45,6 @@ inline void wait_for_conn(std::atomic<bool> &c) {
 /// Waits enough time for us to receive a reply from a localhost remote.
 inline void reply_sleep() { std::this_thread::sleep_for(10ms); }
 
-// Catch2 macros aren't thread safe, so guard with a mutex
-inline std::unique_lock<std::mutex> catch_lock() {
-    static std::mutex mutex;
-    return std::unique_lock<std::mutex>{mutex};
-}
-
 inline OxenMQ::Logger get_logger(std::string prefix = "") {
     std::string me = "tests/common.h";
     std::string strip = __FILE__;
diff --git a/tests/test_commands.cpp b/tests/test_commands.cpp
index b0c4e24..606fed3 100644
--- a/tests/test_commands.cpp
+++ b/tests/test_commands.cpp
@@ -173,18 +173,26 @@ TEST_CASE("deferred replies on incoming connections", "[commands][hey google]")
 
     server.add_category("hey google", Access{AuthLevel::none});
     server.add_request_command("hey google", "remember", [&](Message& m) {
-            auto l = catch_lock();
-            subscribers.emplace_back(m.conn, std::string{m.data[0]});
+            bool bd;
+            {
+                auto l = catch_lock();
+                subscribers.emplace_back(m.conn, std::string{m.data[0]});
+                bd = (bool) backdoor;
+            }
             m.send_reply("Okay, I'll remember that.");
 
-            if (backdoor)
+            if (bd)
                 m.oxenmq.send(backdoor, "backdoor.data", m.data[0]);
     });
     server.add_command("hey google", "recall", [&](Message& m) {
-            auto l = catch_lock();
-            for (auto& s : subscribers) {
-                server.send(s.first, "personal.detail", s.second);
+            decltype(subscribers) subs;
+            {
+                auto l = catch_lock();
+                subs = subscribers;
             }
+
+            for (auto& s : subs)
+                server.send(s.first, "personal.detail", s.second);
     });
     server.add_command("hey google", "install backdoor", [&](Message& m) {
             auto l = catch_lock();
@@ -363,7 +371,7 @@ TEST_CASE("send failure callbacks", "[commands][queue_full]") {
     }
 }
 
-TEST_CASE("data parts", "[send][data_parts]") {
+TEST_CASE("data parts", "[commands][send][data_parts]") {
     std::string listen = random_localhost();
     OxenMQ server{
         "", "", // generate ephemeral keys
@@ -446,7 +454,7 @@ TEST_CASE("data parts", "[send][data_parts]") {
     }
 }
 
-TEST_CASE("deferred replies", "[send][deferred]") {
+TEST_CASE("deferred replies", "[commands][send][deferred]") {
     std::string listen = random_localhost();
     OxenMQ server{
         "", "", // generate ephemeral keys
@@ -461,9 +469,9 @@ TEST_CASE("deferred replies", "[send][deferred]") {
     server.add_request_command("public", "echo", [&](Message& m) {
         std::string msg = m.data.empty() ? ""s : std::string{m.data.front()};
         std::thread t{[send=m.send_later(), msg=std::move(msg)] {
-            { auto lock = catch_lock(); INFO("sleeping"); }
+            { auto lock = catch_lock(); UNSCOPED_INFO("sleeping"); }
             std::this_thread::sleep_for(50ms);
-            { auto lock = catch_lock(); INFO("sending"); }
+            { auto lock = catch_lock(); UNSCOPED_INFO("sending"); }
             send.reply(msg);
         }};
         t.detach();
@@ -472,8 +480,8 @@ TEST_CASE("deferred replies", "[send][deferred]") {
     server.start();
 
     OxenMQ client(
-        [](LogLevel, const char* file, int line, std::string msg) { std::cerr << file << ":" << line << " --C-- " << msg << "\n"; }
-        );
+        get_logger("C» "),
+        LogLevel::trace);
     //client.log_level(LogLevel::trace);
 
     client.start();