qa-tests: Log expected output in debug

hodlinator · hodlinator · commit 356883f0e48b · 2025-12-17T11:20:19.000+01:00
Helpful when comparing expected/unexpected outputs against each other for working/broken code.

Also account for TimeoutExpired.output being None and halt instead of re-raising.
diff --git a/test/functional/feature_framework_startup_failures.py b/test/functional/feature_framework_startup_failures.py
@@ -36,22 +36,24 @@ 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:
             output = subprocess.run(args, timeout=60 * self.options.timeout_factor,
                                     stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True).stdout
         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>",
-                  file=sys.stderr)
-            raise
+            sys.exit("Unexpected child process timeout!\n"
+                     "WARNING: Timeouts like this halt execution of TestNode logic, "
+                     "meaning dangling bitcoind processes are to be expected.\n" +
+                     (format_child_output(e.output.decode("utf-8")) if e.output else "<EMPTY OUTPUT>"))
 
         errors = []
         if (n := output.count("Traceback")) != 1:
@@ -61,13 +63,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."),
