qa: Avoid knock-on exception in assert_start_raises_init_error #32929

pull hodlinator wants to merge 6 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.

    Before:

     02025-07-08T20:05:48.407001Z TestFramework (ERROR): Assertion failed
 1Traceback (most recent call last):
 2  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 686, in assert_start_raises_init_error
 3    ret = self.process.wait(timeout=self.rpc_timeout)
 4          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 5  File "/nix/store/fqm9bqqlmaqqr02qbalm1bazp810qfiw-python3-3.12.9/lib/python3.12/subprocess.py", line 1266, in wait
 6    return self._wait(timeout=timeout)
 7           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
 8  File "/nix/store/fqm9bqqlmaqqr02qbalm1bazp810qfiw-python3-3.12.9/lib/python3.12/subprocess.py", line 2053, in _wait
 9    raise TimeoutExpired(self.args, timeout)
10subprocess.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
11
12During handling of the above exception, another exception occurred:
13
14Traceback (most recent call last):
15  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 186, in main
16    self.setup()
17  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 358, in setup
18    self.setup_network()
19  File "/home/hodlinator/bitcoin/build/test/functional/feature_framework_startup_failures.py", line 151, in setup_network
20    self.nodes[0].assert_start_raises_init_error()
21  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 716, in assert_start_raises_init_error
22    self._raise_assertion_error(assert_msg)
23  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 196, in _raise_assertion_error
24    raise AssertionError(self._node_msg(msg))
25AssertionError: [node 0] bitcoind should have exited within 3s with an error

    After:

     02025-07-08T20:09:15.330589Z TestFramework (ERROR): Assertion failed
 1Traceback (most recent call last):
 2  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 186, in main
 3    self.setup()
 4  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_framework.py", line 358, in setup
 5    self.setup_network()
 6  File "/home/hodlinator/bitcoin/build/test/functional/feature_framework_startup_failures.py", line 151, in setup_network
 7    self.nodes[0].assert_start_raises_init_error()
 8  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 720, in assert_start_raises_init_error
 9    self._raise_assertion_error(assert_msg)
10  File "/home/hodlinator/bitcoin/test/functional/test_framework/test_node.py", line 196, in _raise_assertion_error
11    raise AssertionError(self._node_msg(msg))
12AssertionError: [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'])

    Can be tested on this PR by:

    1. Execute test containing new test case: 
      0build/test/functional/feature_framework_startup_failures.py -ldebug > after.log
    2. Drop first commit which contains the fix.
    3. Re-run test: 
      0build/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

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

    Code Coverage & Benchmarks

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

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK l0rinc
    Concept ACK furszy
    Stale ACK ryanofsky

    If your review is incorrectly listed, please copy-paste <!–meta-tag:bot-skip–> into the comment that the bot should ignore.

    Conflicts

    No conflicts as of last run.

  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

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

    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.

  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:130 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. qa: 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
    9481948e0d
  22. doc: Make comment more pythonic 
    Exceptions are raised in Python, not thrown.
    0ff7425385
  23. hodlinator force-pushed on Dec 3, 2025
  24. 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.

  25. furszy commented at 3:01 pm on December 3, 2025: member
    Concept ACK, cool stuff
  26. DrahtBot removed the label Needs rebase on Dec 3, 2025
  27. qa: assert_start_raises_init_error - Don't trigger as knock-on exception 
    Prevents "During handling of the above exception, another exception occurred"-output which re-raising within the except-block would trigger.
    d7ff1d0fa5
  28. refactor(qa): Extract InternalDurationTestMixin for use in next commit 75102c28a4
  29. qa: Add test for init error timeout behavior c06a8ee186
  30. qa: 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.
    6b0eac750f
  31. hodlinator force-pushed on Dec 3, 2025
  32. 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

     0diff --git a/test/functional/feature_framework_startup_failures.py b/test/functional/feature_framework_startup_failures.py
 1--- a/test/functional/feature_framework_startup_failures.py	(revision 298789b8cbc7283fd868934c615390b98943ebba)
 2+++ b/test/functional/feature_framework_startup_failures.py	(date 1764794284420)
 3@@ -50,12 +50,10 @@
 4             output = subprocess.run(args, timeout=60 * self.options.timeout_factor,
 5                                     stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True).stdout
 6         except subprocess.TimeoutExpired as e:
 7-            print("Unexpected child process timeout!\n"
 8-                  "WARNING: Timeouts like this halt execution of TestNode logic, "
 9-                  "meaning dangling bitcoind processes are to be expected.\n" +
10-                  format_child_output(e.output.decode('utf-8')),
11-                  file=sys.stderr)
12-            raise
13+            sys.exit("Unexpected child process timeout!\n"
14+                     "WARNING: Timeouts like this halt execution of TestNode logic, "
15+                     "meaning dangling bitcoind processes are to be expected.\n" +
16+                     (format_child_output(e.output.decode("utf-8")) if e.output else "<EMPTY OUTPUT>"))
17 
18         errors = []
19         if (n := output.count("Traceback")) != 1:
20Index: test/functional/test_framework/test_node.py
21IDEA additional info:
22Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
23<+>UTF-8
24===================================================================
25diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
26--- a/test/functional/test_framework/test_node.py	(revision 298789b8cbc7283fd868934c615390b98943ebba)
27+++ b/test/functional/test_framework/test_node.py	(date 1764794352084)
28@@ -712,8 +712,8 @@
29         extra_args: extra arguments to pass through to bitcoind
30         expected_msg: regex that stderr should match when bitcoind fails
31 
32-        Will throw if bitcoind starts without an error.
33-        Will throw if an expected_msg is provided and it does not match bitcoind's stdout."""
34+        Will raise if bitcoind starts without an error.
35+        Will raise if an expected_msg is provided and it does not match bitcoind's stdout."""
36         assert not self.running
37         with tempfile.NamedTemporaryFile(dir=self.stderr_dir, delete=False) as log_stderr, \
38              tempfile.NamedTemporaryFile(dir=self.stdout_dir, delete=False) as log_stdout:
  33. DrahtBot requested review from ryanofsky on Dec 3, 2025
  34. DrahtBot requested review from furszy on Dec 3, 2025
  35. 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.


hodlinator DrahtBot fanquake maflcko ryanofsky l0rinc furszy


furszy ryanofsky

Labels
Tests

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: 2025-12-08 21:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me