qa: Clarify assert_start_raises_init_error output #32929

pull hodlinator wants to merge 5 commits into bitcoin:master from hodlinator:2025/07/raise_outside_except changing 2 files +55 −17
  1. hodlinator commented at 9:39 PM on July 9, 2025: contributor

    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:
      build/test/functional/feature_framework_startup_failures.py -ldebug > after.log
    2. Drop first commit which contains the fix.
    3. Re-run test:
      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 (https://github.com/bitcoin/bitcoin/pull/32835#issue-3188748624) which triggered expected timeouts, but with the extra error noise.

  2. DrahtBot added the label Tests on Jul 9, 2025
  3. DrahtBot commented at 9:39 PM on July 9, 2025: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    <!--006a51241073e994b41acfe9ec718e94-->

    Code Coverage & Benchmarks

    For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/32929.

    <!--021abf342d371248e50ceaed478a90ca-->

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK ryanofsky, l0rinc, furszy

    If your review is incorrectly listed, please copy-paste <code>&lt;!--meta-tag:bot-skip--&gt;</code> into the comment that the bot should ignore.

    <!--174a7506f384e20aa4161008e828411d-->

    Conflicts

    No conflicts as of last run.

    <!--5faf32d7da4f0f540f40219e4f7537a3-->

  4. hodlinator force-pushed on Jul 9, 2025
  5. DrahtBot added the label CI failed on Jul 9, 2025
  6. DrahtBot commented at 9:47 PM on July 9, 2025: contributor

    <!--85328a0da195eb286784d51f73fa0af9-->

    🚧 At least one of the CI tasks failed. <sub>Task lint: https://github.com/bitcoin/bitcoin/runs/45676665634</sub> <sub>LLM reason (✨ experimental): Lint check failed due to a Python f-string syntax error in the code.</sub>

    <details><summary>Hints</summary>

    Try to run the tests locally, according to the documentation. However, a CI failure may still happen due to a number of reasons, for example:

    • Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.

    • A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.

    • An intermittent issue.

    Leave a comment here, if you need help tracking down a confusing failure.

    </details>

  7. fanquake commented at 10:05 AM on July 10, 2025: member

    (Test failure here was fixed in #32932)

  8. hodlinator force-pushed on Jul 11, 2025
  9. DrahtBot removed the label CI failed on Jul 11, 2025
  10. achow101 requested review from ryanofsky on Oct 22, 2025
  11. achow101 requested review from l0rinc on Oct 22, 2025
  12. maflcko commented at 10:51 AM on October 27, 2025: member

    No objections, but in this case, it seems beneficial (or at least harmless) to list the init args, which could help debug why the init error was not raised?

  13. hodlinator force-pushed on Oct 27, 2025
  14. hodlinator commented at 3:13 PM on October 27, 2025: contributor

    No objections, but in this case, it seems beneficial (or at least harmless) to list the init args, which could help debug why the init error was not raised?

    Good point, that information from the initial exception was no longer included. Added back in latest push & updated PR description example output.

  15. ryanofsky approved
  16. ryanofsky commented at 4:40 PM on October 27, 2025: contributor

    Code review ACK fde4d2f0e1cf1252cbb24aad475332d96f3e6e80. Very welcome change! I almost always get confused by "During handling of the above exception, another exception occurred" messages, so it is great to eliminate one and stop showing a spurious internal exception before the real error when assert_start_raises_init_error checks fail.

    Implementation of this PR is also a little simpler that it may first appear. The actual fix is small and is in the first commit, and the later commits are confined to the feature_framework_startup_failures.py test, ensuring the fix works, and making minor improvements there.

  17. in test/functional/feature_framework_startup_failures.py:120 in 5dfbb0ca69 outdated 
     116 |          parser.add_argument("--internal_node_start_duration", dest="node_start_duration", help="ONLY TO BE USED WHEN TEST RELAUNCHES ITSELF", type=float)
 117 |          InternalTestMixin.add_options(self, parser)
 118 |  
 119 | +    def get_reasonable_rpc_timeout(self):
 120 | +        # 2 * the measured test startup duration should be enough.
 121 | +        # Divide by timeout_factor to counter multiplication in BitcoinTestFramework.
    l0rinc commented at 8:13 PM on October 27, 2025:

    It's a bit weird that this mixin knows where it will be used, but I guess that's not gonna' change, so it's fine

  18. l0rinc commented at 8:45 PM on October 27, 2025: contributor

    Rebased the change, all tests pass locally. Reverted the first commit, the test did indeed fail as expected. I have reviewed the test code lightly, seems roughly correct.

    Nit: assert_start_raises_init_error originally mixed the terminology and claims the method "throws" and later that it "raises": if you touch again, consider unifying it to be more pythonic. Definitely not a blocker.

    ACK fde4d2f0e1cf1252cbb24aad475332d96f3e6e80

  19. l0rinc approved
  20. DrahtBot added the label Needs rebase on Dec 3, 2025
  21. hodlinator force-pushed on Dec 3, 2025
  22. hodlinator commented at 2:00 PM on December 3, 2025: contributor

    Latest push (42ed679f0bb9807b08e6209528829f1e45f8765d):

    • Rebases to resolve conflict with fab085c15f7221986f73af7e05e799edf3eadaf0
    • Adds 9481948e0d979dccedd7b4e6616ef4903bc1cdba - Reverts one line of fab085c15f7221986f73af7e05e799edf3eadaf0 to fix issue
    • Adds 0ff74253858f0a9b6c1f0fecb815c8380d5661be - Minor documentation change to assert_start_raises_init_error() as requested by #32929 (comment)
    • Modifies last commit 42ed679f0bb9807b08e6209528829f1e45f8765d - Account for e.output being None and halt instead of re-raising exception.

    Edit: Corrected reference to fab085c15f7221986f73af7e05e799edf3eadaf0.

  23. furszy commented at 3:01 PM on December 3, 2025: member

    Concept ACK, cool stuff

  24. DrahtBot removed the label Needs rebase on Dec 3, 2025
  25. hodlinator force-pushed on Dec 3, 2025
  26. l0rinc commented at 8:42 PM on December 3, 2025: contributor

    I have tested the previous ACK, now just reviewed the range-diff and rebased soft-reset, the latest change looks good to me.

    ACK 6b0eac750f3aecb29446d70c039559143e43a011

    <details> <summary>patch since last ACK</summary>

    diff --git a/test/functional/feature_framework_startup_failures.py b/test/functional/feature_framework_startup_failures.py
--- a/test/functional/feature_framework_startup_failures.py	(revision 298789b8cbc7283fd868934c615390b98943ebba)
+++ b/test/functional/feature_framework_startup_failures.py	(date 1764794284420)
@@ -50,12 +50,10 @@
             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" +
-                  format_child_output(e.output.decode('utf-8')),
-                  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:
Index: test/functional/test_framework/test_node.py
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
--- a/test/functional/test_framework/test_node.py	(revision 298789b8cbc7283fd868934c615390b98943ebba)
+++ b/test/functional/test_framework/test_node.py	(date 1764794352084)
@@ -712,8 +712,8 @@
         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:

    </details>

  27. DrahtBot requested review from ryanofsky on Dec 3, 2025
  28. DrahtBot requested review from furszy on Dec 3, 2025
  29. hodlinator commented at 8:42 PM on December 3, 2025: contributor

    Latest push (6b0eac750f3aecb29446d70c039559143e43a011):

    • Restores the " (cmd: ..." addition in d7ff1d0fa572ec36ff1eb10c0a1c04ef5e5be072 which had somehow gone missing in 4eccfae4563933c8499dc6994980d8bb8df53381. The test in c06a8ee18699800a0fa06898251ac7088ea8ef70 had also lost " (cmd:" in ae69cf7bc7ebecd0d58b007a2c556a787554af28, so it's not just a mismerge. Possibly a case of working on multiple computers and not syncing properly between them before force-pushing. Thanks to @l0rinc for finding it.
  30. in test/functional/feature_framework_startup_failures.py:93 in c06a8ee186 
      89 | @@ -90,6 +90,12 @@ def run_test(self):
  90 |              r"AssertionError: \[node 0\] Unable to connect to bitcoind after \d+s \(ignored errors: {[^}]*'OSError \w+'?: \d+[^}]*}, latest: '[\w ]+'/\w+\([^)]+\)\)"
  91 |          )
  92 |  
  93 | +        self.log.info("Verifying timeout while waiting for init errors results in only one exception.")
    ryanofsky commented at 8:39 PM on December 16, 2025:

    In commit "qa: Add test for init error timeout behavior" (c06a8ee18699800a0fa06898251ac7088ea8ef70)

    I was pretty confused by this test because I thought it was supposed to be "waiting for init errors" but didn't see where there were any init errors. Would suggest replacing "waiting for init errors" with something like "waiting for init errors that do not occur" or something like that. Would be good to update this string, but also s/TestInitErrorTimeout/TestMissingInitErrorTimeout/ or similar.

    hodlinator commented at 10:10 AM on December 17, 2025:

    Good points, worth distinguishing it more from the pre-existing TestInitErrorStartupFailure.

  31. ryanofsky commented at 9:11 PM on December 16, 2025: contributor

    Code review ACK 6b0eac750f3aecb29446d70c039559143e43a011. Since last review, just tweaking the last commit and adding two initial commits after some apparent conflicts with other PRs.

    I do think this PR could benefit from being organized better and appearing to have more focus. I would definitely move the third commit d7ff1d0fa572ec36ff1eb10c0a1c04ef5e5be072 first since it's the main commit and probably the one most useful for other developers.

    I also think it would be good to distinguish improvements to the qa framework from improvements to the feature_framework test. I might go with different prefixes in commit titles like:

    • qa: Make assert_start_raises_init_error output more readable
    • qa-tests: Bring back decoding of exception field
    • qa-tests: refactor: Extract InternalDurationTestMixin for use in next commit
    • qa-tests: Add test for missing init errors
    • qa-tests: Log expected output in debug
    • doc: Make comment more pythonic
  32. qa: Improve assert_start_raises_init_error output
    Re-raising within the except-block would trigger excessive "During handling of the above exception, another exception occurred"-output.

Also changed comment - exceptions are raised in Python, not thrown.
    fb43b2f8cc
  33. fix(qa-tests): Bring back decoding of exception field
    Partial revert of fab085c15f7221986f73af7e05e799edf3eadaf0

subprocess.run(..., text=True) is not sufficient to make the TimeoutExpired exception stop using byte buffers. This is a known issue, see: https://github.com/python/cpython/issues/87597
    69bcfcad8c
  34. refactor(qa-tests): Extract InternalDurationTestMixin for use in next commit d7f703c1f1
  35. qa-tests: Add test for timeouts due to missing init errors
    Verifies that the fix to assert_start_raises_init_error in an earlier commit stays intact, with only one exception being raised instead of multiple.
    7427a03b5a
  36. qa-tests: Log expected output in debug
    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.
    356883f0e4
  37. hodlinator force-pushed on Dec 17, 2025
  38. hodlinator commented at 10:23 AM on December 17, 2025: contributor

    Latest push (6b0eac750f3aecb29446d70c039559143e43a011 -> 356883f0e48be59bcb154096cef82cbf3f0dd9d8) was largely motivated by #32929#pullrequestreview-3584856747 and contains changes:

  39. ryanofsky approved
  40. ryanofsky commented at 5:42 PM on December 17, 2025: contributor

    Code review ACK 356883f0e48be59bcb154096cef82cbf3f0dd9d8. Thanks for the updates! Just rearranged commits and made minor changes in "missing init errors" test since last review

    Might also suggest renaming PR to "qa: Make assert_start_raises_init_error output more readable" to motivate it a little more. Current title is fine but to me me at least it wasn't obvious what a knock-on exception what the benefit would be of avoiding it.

  41. DrahtBot requested review from l0rinc on Dec 17, 2025
  42. l0rinc commented at 7:52 PM on December 17, 2025: contributor

    Only reviewed the diff since my last ack which only contains the rename and a description update - and some commit structure and message changes which I was already fine with before.

    Might also suggest renaming PR to "qa: Make assert_start_raises_init_error output more readable"

    The PR has a PR problem

    ACK 356883f0e48be59bcb154096cef82cbf3f0dd9d8

  43. furszy commented at 8:26 PM on December 17, 2025: member

    Code ACK 356883f0e48be59bcb154096cef82cbf3f0dd9d8

  44. hodlinator renamed this:
    qa: Avoid knock-on exception in assert_start_raises_init_error
    qa: Clarify assert_start_raises_init_error output
    on Dec 18, 2025
  45. glozow merged this on Dec 22, 2025
  46. glozow closed this on Dec 22, 2025
  47. sedited referenced this in commit f8db928648 on Dec 27, 2025
  48. joshdoman referenced this in commit 57661ceac9 on Dec 27, 2025
  49. stickies-v referenced this in commit 9fa736f8e4 on Jan 22, 2026
  50. stringintech referenced this in commit f651a10526 on Feb 1, 2026
  51. hodlinator deleted the branch on Apr 9, 2026
Contributors
hodlinatorDrahtBotfanquakemaflckoryanofskyl0rincfurszy


l0rinc

Labels
Tests
Linked (view graph)
#32835 test: fix feature_init.py intermittencies
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-04-19 03:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me