qa: Log expected output in debug

hodlinator · hodlinator · commit fde4d2f0e1cf · 2025-10-27T15:51:53.000+01:00
Helpful when comparing expected/unexpected outputs against each other for working/broken code.
diff --git a/test/functional/feature_framework_startup_failures.py b/test/functional/feature_framework_startup_failures.py
@@ -36,11 +36,15 @@ def setup_network(self):
     # Launches a child test process that runs this same file, but instantiates
     # a child test. Verifies that it raises only the expected exception, once.
     def _verify_startup_failure(self, test, internal_args, expected_exception):
+        name = test.__name__
+        def format_child_output(output):
+            return f"\n<{name} OUTPUT BEGIN>\n{output.strip()}\n<{name} OUTPUT END>\n"
+
         # Inherit sys.argv from parent, only overriding tmpdir to a subdirectory
         # so children don't fail due to colliding with the parent dir.
         assert self.options.tmpdir, "Framework should always set tmpdir."
         subdir = md5(expected_exception.encode('utf-8')).hexdigest()[:8]
-        args = [sys.executable] + sys.argv + [f"--tmpdir={self.options.tmpdir}/{subdir}", f"--internal_test={test.__name__}"] + internal_args
+        args = [sys.executable] + sys.argv + [f"--tmpdir={self.options.tmpdir}/{subdir}", f"--internal_test={name}"] + internal_args
 
         try:
             # The subprocess encoding argument gives different results for e.output
@@ -50,8 +54,8 @@ def _verify_startup_failure(self, test, internal_args, expected_exception):
         except subprocess.TimeoutExpired as e:
             print("Unexpected child process timeout!\n"
                   "WARNING: Timeouts like this halt execution of TestNode logic, "
-                  "meaning dangling bitcoind processes are to be expected.\n"
-                  f"<CHILD OUTPUT BEGIN>\n{e.output.decode('utf-8')}\n<CHILD OUTPUT END>",
+                  "meaning dangling bitcoind processes are to be expected.\n" +
+                  format_child_output(e.output.decode('utf-8')),
                   file=sys.stderr)
             raise
 
@@ -63,13 +67,17 @@ def _verify_startup_failure(self, test, internal_args, expected_exception):
         if (n := output.count("Test failed. Test logging available at")) != 1:
             errors.append(f"Found {n}/1 test failure output messages.")
 
-        assert not errors, f"Child test didn't contain (only) expected errors:\n{linesep.join(errors)}\n<CHILD OUTPUT BEGIN>\n{output}\n<CHILD OUTPUT END>\n"
+        assert not errors, (f"Child test did NOT contain (only) expected errors:\n{linesep.join(errors)}\n" +
+                            format_child_output(output))
+
+        self.log.debug("Child test did contain (only) expected errors:\n" +
+                       format_child_output(output))
 
     def run_test(self):
         self.log.info("Verifying _verify_startup_failure() functionality (self-check).")
         assert_raises_message(
             AssertionError,
-            ( "Child test didn't contain (only) expected errors:\n"
+            ( "Child test did NOT contain (only) expected errors:\n"
              f"Found 0/1 tracebacks - expecting exactly one with no knock-on exceptions.{linesep}"
              f"Found 0/1 occurrences of the specific exception: NonExistentError{linesep}"
               "Found 0/1 test failure output messages."),
