Merge bitcoin/bitcoin#32929: qa: Clarify assert_start_raises_init_error output

356883f qa-tests: Log expected output in debug (Hodlinator)
7427a03 qa-tests: Add test for timeouts due to missing init errors (Hodlinator)
d7f703c refactor(qa-tests): Extract InternalDurationTestMixin for use in next commit (Hodlinator)
69bcfca fix(qa-tests): Bring back decoding of exception field (Hodlinator)
fb43b2f qa: Improve assert_start_raises_init_error output (Hodlinator)

Pull request description:

  Raising a new exception from within a Python `except`-block, as `assert_start_raises_init_error()` does, causes the interpreter to generate extra error output which is unnecessary in this case.

  <details><summary>Example output before & after this PR</summary>

  Before:
  ```
  2025-07-08T20:05:48.407001Z TestFramework (ERROR): Assertion failed
  Traceback (most recent call last):
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 686, in assert_start_raises_init_error
      ret = self.process.wait(timeout=self.rpc_timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    File "/nix/store/fqm9bqqlmaqqr02qbalm1bazp810qfiw-python3-3.12.9/lib/python3.12/subprocess.py", line 1266, in wait
      return self._wait(timeout=timeout)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^
    File "/nix/store/fqm9bqqlmaqqr02qbalm1bazp810qfiw-python3-3.12.9/lib/python3.12/subprocess.py", line 2053, in _wait
      raise TimeoutExpired(self.args, timeout)
  subprocess.TimeoutExpired: Command '['/home/hodlinator/bitcoin/build/bin/bitcoind', '-datadir=/tmp/bitcoin_func_test_v96lkcq8/eb2665c7/node0', '-logtimemicros', '-debug', '-debugexclude=libevent', '-debugexclude=leveldb', '-debugexclude=rand', '-uacomment=testnode0', '-disablewallet', '-logthreadnames', '-logsourcelocations', '-loglevel=trace', '-v2transport=0']' timed out after 3 seconds

  During handling of the above exception, another exception occurred:

  Traceback (most recent call last):
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 186, in main
      self.setup()
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 358, in setup
      self.setup_network()
    File "/home/hodlinator/bitcoin/build/test/functional/feature_framework_startup_failures.py", line 151, in setup_network
      self.nodes[0].assert_start_raises_init_error()
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 716, in assert_start_raises_init_error
      self._raise_assertion_error(assert_msg)
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 196, in _raise_assertion_error
      raise AssertionError(self._node_msg(msg))
  AssertionError: [node 0] bitcoind should have exited within 3s with an error
  ```
  After:
  ```
  2025-07-08T20:09:15.330589Z TestFramework (ERROR): Assertion failed
  Traceback (most recent call last):
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 186, in main
      self.setup()
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 358, in setup
      self.setup_network()
    File "/home/hodlinator/bitcoin/build/test/functional/feature_framework_startup_failures.py", line 151, in setup_network
      self.nodes[0].assert_start_raises_init_error()
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 720, in assert_start_raises_init_error
      self._raise_assertion_error(assert_msg)
    File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 196, in _raise_assertion_error
      raise AssertionError(self._node_msg(msg))
  AssertionError: [node 0] bitcoind should have exited within 3s with an error (cmd: ['/home/hodlinator/bitcoin/build/bin/bitcoind', '-datadir=/tmp/bitcoin_func_test_v96lkcq8/eb2665c7/node0', '-logtimemicros', '-debug', '-debugexclude=libevent', '-debugexclude=leveldb', '-debugexclude=rand', '-uacomment=testnode0', '-disablewallet', '-logthreadnames', '-logsourcelocations', '-loglevel=trace', '-v2transport=0'])
  ```

  </details>

  ---

  Can be tested on this PR by:
  1. Execute test containing new test case:
      ```shell
      build/test/functional/feature_framework_startup_failures.py -ldebug > after.log
      ```
  2. Drop first commit which contains the fix.
  3. Re-run test:
      ```shell
      build/test/functional/feature_framework_startup_failures.py -ldebug > before.log
      ```
  4. Diff logs, focusing on `TestInitErrorTimeout OUTPUT` sections.

  ---

  Found while testing #32835 using the suggested method (bitcoin/bitcoin#32835 (comment)) which triggered expected timeouts, but with the extra error noise.

ACKs for top commit:
  l0rinc:
    ACK 356883f
  ryanofsky:
    Code review ACK 356883f. Thanks for the updates! Just rearranged commits and made minor changes in "missing init errors" test since last review
  furszy:
    Code ACK 356883f

Tree-SHA512: 01f2f1f6a5e79cf83a39a143cfb8b2bb8360e0402e91a97a7df8254309fd4436a55468d11825093c052010bfce57f3461d912a578cd2594114aba435ab48b999

Author: glozow

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}\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."),
@@ -76,7 +82,7 @@ def run_test(self):
             "NonExistentError",
         )
 
-        self.log.info("Parent process is measuring node startup duration in order to obtain a reasonable timeout value for later test...")
+        self.log.info("Parent process is measuring node startup duration in order to obtain a reasonable timeout value for later tests...")
         node_start_time = time.time()
         self.nodes[0].start()
         self.nodes[0].wait_for_rpc_connection()
@@ -90,6 +96,12 @@ def run_test(self):
             r"AssertionError: \[node 0\] Unable to connect to bitcoind after \d+s \(ignored errors: {[^}]*'OSError \w+'?: \d+[^}]*}, latest: '[\w ]+'/\w+\([^)]+\)\)"
         )
 
+        self.log.info("Verifying timeout while waiting for init errors that do not occur results in only one exception.")
+        self._verify_startup_failure(
+            TestMissingInitErrorTimeout, [f"--internal_node_start_duration={node_start_duration}"],
+            r"AssertionError: \[node 0\] bitcoind should have exited within \d+s with an error \(cmd:"
+        )
+
         self.log.info("Verifying startup failure due to invalid arg results in only one exception.")
         self._verify_startup_failure(
             TestInitErrorStartupFailure, [],
@@ -107,20 +119,41 @@ def add_options(self, parser):
         # Just here to silence unrecognized argument error, we actually read the value in the if-main at the bottom.
         parser.add_argument("--internal_test", dest="internal_never_read", help="ONLY TO BE USED WHEN TEST RELAUNCHES ITSELF")
 
-class TestWrongRpcPortStartupFailure(InternalTestMixin, BitcoinTestFramework):
+class InternalDurationTestMixin(InternalTestMixin):
     def add_options(self, parser):
+        # Receives the previously measured duration for node startup + RPC connection establishment.
         parser.add_argument("--internal_node_start_duration", dest="node_start_duration", help="ONLY TO BE USED WHEN TEST RELAUNCHES ITSELF", type=float)
         InternalTestMixin.add_options(self, parser)
 
+    def get_reasonable_rpc_timeout(self):
+        # 2 * the measured test startup duration should be enough.
+        # Divide by timeout_factor to counter multiplication in BitcoinTestFramework.
+        return max(3, 2 * self.options.node_start_duration) / self.options.timeout_factor
+
+class TestWrongRpcPortStartupFailure(InternalDurationTestMixin, BitcoinTestFramework):
     def set_test_params(self):
         self.num_nodes = 1
         # Override RPC listen port to something TestNode isn't expecting so that
         # we are unable to establish an RPC connection.
         self.extra_args = [[f"-rpcport={rpc_port(2)}"]]
         # Override the timeout to avoid waiting unnecessarily long to realize
-        # nothing is on that port. Divide by timeout_factor to counter
-        # multiplication in base, 2 * node_start_duration should be enough.
-        self.rpc_timeout = max(3, 2 * self.options.node_start_duration) / self.options.timeout_factor
+        # nothing is on that port.
+        self.rpc_timeout = self.get_reasonable_rpc_timeout()
+
+    def run_test(self):
+        assert False, "Should have failed earlier during startup."
+
+class TestMissingInitErrorTimeout(InternalDurationTestMixin, BitcoinTestFramework):
+    def set_test_params(self):
+        self.num_nodes = 1
+        # Override the timeout to avoid waiting unnecessarily long for an init
+        # error which never occurs.
+        self.rpc_timeout = self.get_reasonable_rpc_timeout()
+
+    def setup_network(self):
+        self.add_nodes(self.num_nodes, self.extra_args)
+        self.nodes[0].assert_start_raises_init_error()
+        assert False, "assert_start_raises_init_error() should raise an exception due to timeout since we don't expect an init error."
 
     def run_test(self):
         assert False, "Should have failed earlier during startup."

test/functional/test_framework/test_node.py

@@ -717,11 +717,12 @@ def assert_start_raises_init_error(self, extra_args=None, expected_msg=None, mat
         extra_args: extra arguments to pass through to bitcoind
         expected_msg: regex that stderr should match when bitcoind fails
 
-        Will throw if bitcoind starts without an error.
-        Will throw if an expected_msg is provided and it does not match bitcoind's stdout."""
+        Will raise if bitcoind starts without an error.
+        Will raise if an expected_msg is provided and it does not match bitcoind's stdout."""
         assert not self.running
         with tempfile.NamedTemporaryFile(dir=self.stderr_dir, delete=False) as log_stderr, \
              tempfile.NamedTemporaryFile(dir=self.stdout_dir, delete=False) as log_stdout:
+            assert_msg = None
             try:
                 self.start(extra_args, stdout=log_stdout, stderr=log_stderr, *args, **kwargs)
                 ret = self.process.wait(timeout=self.rpc_timeout)
@@ -745,7 +746,7 @@ def assert_start_raises_init_error(self, extra_args=None, expected_msg=None, mat
                         if expected_msg != stderr:
                             self._raise_assertion_error(
                                 'Expected message "{}" does not fully match stderr:\n"{}"'.format(expected_msg, stderr))
-            except subprocess.TimeoutExpired:
+            except subprocess.TimeoutExpired as e:
                 self.process.kill()
                 self.running = False
                 self.process = None
@@ -754,6 +755,10 @@ def assert_start_raises_init_error(self, extra_args=None, expected_msg=None, mat
                     assert_msg += "with an error"
                 else:
                     assert_msg += "with expected error " + expected_msg
+                assert_msg += f" (cmd: {e.cmd})"
+
+            # Raise assertion outside of except-block above in order for it not to be treated as a knock-on exception.
+            if assert_msg:
                 self._raise_assertion_error(assert_msg)
 
     def add_p2p_connection(self, p2p_conn, *, wait_for_verack=True, send_version=True, supports_v2_p2p=None, wait_for_v2_handshake=True, expect_success=True, **kwargs):