From 967a83ef4522d4c84a19dc04165d7c60222b6b56 Mon Sep 17 00:00:00 2001
From: Eddy Ashton <edashton@microsoft.com>
Date: Wed, 3 Jul 2024 16:49:53 +0100
Subject: [PATCH] `fuzz_test`: Reduce logging spam at allocation quotas, to
 avoid test timeouts (#6324)

---
 src/host/main.cpp |  8 ++++++--
 src/host/tcp.h    | 19 ++++++++++++++-----
 tests/fuzzing.py  | 11 ++++++++++-
 3 files changed, 30 insertions(+), 8 deletions(-)

diff --git a/src/host/main.cpp b/src/host/main.cpp
index 925fcbe20d61..f6eae847a803 100644
--- a/src/host/main.cpp
+++ b/src/host/main.cpp
@@ -48,8 +48,12 @@ using namespace std::chrono_literals;
 using ResolvedAddresses = std::
   map<ccf::NodeInfoNetwork::RpcInterfaceID, ccf::NodeInfoNetwork::NetAddress>;
 
-size_t asynchost::TCPImpl::remaining_read_quota;
-size_t asynchost::UDPImpl::remaining_read_quota;
+size_t asynchost::TCPImpl::remaining_read_quota =
+  asynchost::TCPImpl::max_read_quota;
+bool asynchost::TCPImpl::alloc_quota_logged = false;
+
+size_t asynchost::UDPImpl::remaining_read_quota =
+  asynchost::UDPImpl::max_read_quota;
 
 std::chrono::microseconds asynchost::TimeBoundLogger::default_max_time(10'000);
 
diff --git a/src/host/tcp.h b/src/host/tcp.h
index 18cf169dcafc..0f0fbf92fc56 100644
--- a/src/host/tcp.h
+++ b/src/host/tcp.h
@@ -29,6 +29,7 @@ namespace asynchost
     // Each uv iteration, read only a capped amount from all sockets.
     static constexpr auto max_read_quota = max_read_size * 4;
     static size_t remaining_read_quota;
+    static bool alloc_quota_logged;
 
     enum Status
     {
@@ -127,6 +128,7 @@ namespace asynchost
     static void reset_read_quota()
     {
       remaining_read_quota = max_read_quota;
+      alloc_quota_logged = false;
     }
 
     void set_behaviour(std::unique_ptr<SocketBehaviour<TCP>> b)
@@ -743,10 +745,13 @@ namespace asynchost
 
       alloc_size = std::min(alloc_size, remaining_read_quota);
       remaining_read_quota -= alloc_size;
-      LOG_TRACE_FMT(
-        "Allocating {} bytes for TCP read ({} of quota remaining)",
-        alloc_size,
-        remaining_read_quota);
+      if (alloc_size != 0)
+      {
+        LOG_TRACE_FMT(
+          "Allocating {} bytes for TCP read ({} of quota remaining)",
+          alloc_size,
+          remaining_read_quota);
+      }
 
       buf->base = new char[alloc_size];
       buf->len = alloc_size;
@@ -772,7 +777,11 @@ namespace asynchost
 
       if (sz == UV_ENOBUFS)
       {
-        LOG_DEBUG_FMT("TCP on_read reached allocation quota");
+        if (!alloc_quota_logged)
+        {
+          LOG_DEBUG_FMT("TCP on_read reached allocation quota");
+          alloc_quota_logged = true;
+        }
         on_free(buf);
         return;
       }
diff --git a/tests/fuzzing.py b/tests/fuzzing.py
index afb63c1d7007..887ed8891c51 100644
--- a/tests/fuzzing.py
+++ b/tests/fuzzing.py
@@ -14,6 +14,7 @@ def __init__(self, print_period=datetime.timedelta(seconds=3), keep_lines=50):
         self.print_period = print_period
         self.last_printed = None
         self.keep_lines = keep_lines
+        self.last_fuzzed_count = 0
 
         self.session = None
 
@@ -24,10 +25,15 @@ def _store_line(self, s):
         if self.session is not None:
             now = datetime.datetime.now()
             if self.last_printed is None or now - self.last_printed > self.print_period:
+                fuzzed_this_period = (
+                    self.session.num_cases_actually_fuzzed - self.last_fuzzed_count
+                )
+                fuzzing_rate = fuzzed_this_period / self.print_period.seconds
                 LOG.info(
-                    f"Fuzzed {self.session.num_cases_actually_fuzzed} total cases in {self.session.runtime:.2f}s (rate={self.session.exec_speed:.2f}/s)"
+                    f"Fuzzed {self.session.num_cases_actually_fuzzed} total cases in {self.session.runtime:.2f}s (current rate={fuzzing_rate:.2f}/s)"
                 )
                 self.last_printed = now
+                self.last_fuzzed_count = self.session.num_cases_actually_fuzzed
 
     def open_test_case(self, test_case_id, name, index, *args, **kwargs):
         self._store_line(f"Test case: {name} ({index=})")
@@ -149,6 +155,7 @@ def fuzz_node_to_node(network, args):
     )
     fuzz_logger.session = session
 
+    LOG.info(f"Loggers before monkey-patch: {session._fuzz_data_logger._fuzz_loggers}")
     # Monkey-patch: Remove any Db loggers from the boofuzz session. We never
     # use them, and they're reliant on disk IO (for db commits) so sometimes very slow
     session._fuzz_data_logger._fuzz_loggers = [
@@ -156,6 +163,8 @@ def fuzz_node_to_node(network, args):
         for logger in session._fuzz_data_logger._fuzz_loggers
         if not isinstance(logger, boofuzz.fuzz_logger_db.FuzzLoggerDb)
     ]
+    session._db_logger = None
+    LOG.info(f"Loggers after monkey-patch: {session._fuzz_data_logger._fuzz_loggers}")
 
     session.connect(req)