test: fix `assert_debug_log` call-site bugs, add type checks #28645

pull theStack wants to merge 1 commits into bitcoin:master from theStack:202310-test-enforce_assert_debug_log_list_params changing 3 files +7 −4
  1. theStack commented at 3:50 PM on October 12, 2023: contributor

    Two recently added tests (PR #28625 / commit 2e31250027ac580a7a72221fe2ff505b30836175 and PR #28634 / commit 3bb51c29df596aab2c1fde184667cee435597715) introduced bugs by wrongly using the assert_debug_log helper:

    https://github.com/bitcoin/bitcoin/blob/5ea4fc05edde66c5c90383bc054590dfbdb2b645/test/functional/feature_assumeutxo.py#L84-L85 (already fixed in #28639)

    https://github.com/bitcoin/bitcoin/blob/5ea4fc05edde66c5c90383bc054590dfbdb2b645/test/functional/p2p_v2_transport.py#L148 https://github.com/bitcoin/bitcoin/blob/5ea4fc05edde66c5c90383bc054590dfbdb2b645/test/functional/p2p_v2_transport.py#L159

    Instead of passing the expected debug string in a list as expected, it was passed as bare string, which is then interpretered as a list of characters, very likely leading the debug log assertion pass even if the intended message is not appearing. Thanks to maflcko for discovering: #28625 (review)

    In order to avoid bugs like this in the future, enforce that the {un}expected_msgs parameters are lists, as discussed in #28625 (review). Using mypy might be an alternative, but I guess it takes quite a bit of effort to properly integrate this into CI for the whole functional test suite (including taking care of false-positives), so I decided to go with the simpler "manual asserts" hack. Suggestions are very welcome of course.

  2. theStack commented at 3:54 PM on October 12, 2023: contributor

    Can be tested by re-introducing one of the bugs, e.g.:

    diff --git a/test/functional/p2p_v2_transport.py b/test/functional/p2p_v2_transport.py
index 5ad2194b8..8423760e5 100755
--- a/test/functional/p2p_v2_transport.py
+++ b/test/functional/p2p_v2_transport.py
@@ -145,7 +145,7 @@ class V2TransportTest(BitcoinTestFramework):
         wrong_network_magic_prefix = MAGIC_BYTES["signet"] + V1_PREFIX[4:]
         with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
             s.connect(("127.0.0.1", p2p_port(0)))
-            with self.nodes[0].assert_debug_log(["V2 transport error: V1 peer with wrong MessageStart"]):
+            with self.nodes[0].assert_debug_log("V2 transport error: V1 peer with wrong MessageStart"):
                 s.sendall(wrong_network_magic_prefix + b"somepayload")
 
         # Check detection of missing garbage terminator (hits after fixed amount of data if terminator never matches garbage)

    and executing the corresponding test:

    $ ./test/functional/p2p_v2_transport.py                                                                                       
2023-10-12T15:51:32.514000Z TestFramework (INFO): PRNG seed is: 4233183318696227911
2023-10-12T15:51:32.515000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_j5zg66u2
2023-10-12T15:51:39.018000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/thestack/bitcoin/test/functional/test_framework/test_framework.py", line 131, in main
    self.run_test()
  File "/home/thestack/bitcoin/./test/functional/p2p_v2_transport.py", line 148, in run_test
    with self.nodes[0].assert_debug_log("V2 transport error: V1 peer with wrong MessageStart"):
  File "/usr/local/lib/python3.10/contextlib.py", line 135, in __enter__
    return next(self.gen)
  File "/home/thestack/bitcoin/test/functional/test_framework/test_node.py", line 454, in assert_debug_log
    assert_equal(type(expected_msgs), list)
  File "/home/thestack/bitcoin/test/functional/test_framework/util.py", line 57, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(<class 'str'> == <class 'list'>)
  3. DrahtBot commented at 3:54 PM on October 12, 2023: contributor

    <!--e57a25ab6845829454e8d69fc972939a-->

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

    <!--006a51241073e994b41acfe9ec718e94-->

    Code Coverage

    For detailed information about the code coverage, see the test coverage report.

    <!--021abf342d371248e50ceaed478a90ca-->

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK dergoegge, achow101, maflcko
    Stale ACK jonatack

    If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

  4. in test/functional/feature_assumeutxo.py:85 in 616c090e21 outdated 
      81 | @@ -82,7 +82,7 @@ def test_invalid_snapshot_scenarios(self, valid_snapshot_path):
  82 |              f.write(bytes.fromhex(bad_snapshot_block_hash)[::-1] + valid_snapshot_contents[32:])
  83 |  
  84 |          expected_log = f"assumeutxo height in snapshot metadata not recognized ({bad_snapshot_height}) - refusing to load snapshot"
  85 | -        with self.nodes[1].assert_debug_log(expected_log):
  86 | +        with self.nodes[1].assert_debug_log([expected_log]):
    fanquake commented at 4:06 PM on October 12, 2023:

    Note this is also in #28639.

    theStack commented at 10:50 AM on October 13, 2023:

    After rebase, that change is now not included anymore. Mentioned in the PR description that the first of the three instances is already fixed by #28639.

  5. in test/functional/test_framework/test_node.py:452 in 616c090e21 outdated 
     447 | @@ -448,6 +448,12 @@ def debug_log_size(self, **kwargs) -> int:
 448 |      def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
 449 |          if unexpected_msgs is None:
 450 |              unexpected_msgs = []
 451 | +        # enforce that `{un}expected_msgs` are lists, in order to avoid bugs where strings
 452 | +        # are passed as arguments, which would be interpreted as lists of single characters
 453 | +        # (likely always passing the debug log assertion)
 454 | +        assert_equal(type(expected_msgs), list)
 455 | +        assert_equal(type(unexpected_msgs), list)
    jonatack commented at 6:04 PM on October 12, 2023:

    I think you can drop the 3 lines of comments if you retouch, as the assertions are self-documenting.

    (It would be nice if we could enforce something like this; I'm starting to use typing in new code like https://github.com/bitcoin/bitcoin/pull/28116/commits/71c22f1d9a4743119355685e8b01f245067272c0)

     def assert_debug_log(self, expected_msgs: list, unexpected_msgs: Optional[list] = [], timeout: Optional[int] = 2):
    theStack commented at 10:43 AM on October 13, 2023:

    Done with the latest force-push.

    willcl-ark commented at 12:50 PM on October 13, 2023:

    I agree a type hint could be nice here (but not essential).

    I did try to selectively enable this diagnostic for our mypy run in lint-python.py using the --check-untyped-defs option, but this currently returns 747 errors, so we can't be using that just yet...

  6. jonatack commented at 6:06 PM on October 12, 2023: member

    ACK 616c090e21f9c77a75d0ecc3328aa8bd365e0a1

    (If the CI passes. Did it run?)

  7. maflcko commented at 9:17 AM on October 13, 2023: member

    (If the CI passes. Did it run?)

    Needs rebase, due to GitHub downtime, I guess?

  8. maflcko closed this on Oct 13, 2023
  9. maflcko reopened this on Oct 13, 2023
  10. maflcko added this to the milestone 26.0 on Oct 13, 2023
  11. maflcko added the label Needs rebase on Oct 13, 2023
  12. test: fix `assert_debug_log` call-site bugs, add type checks
    Two recently added tests (PR #28625 / commit 2e31250027ac580a7a72221fe2ff505b30836175
and PR #28634 / commit 3bb51c29df596aab2c1fde184667cee435597715)
introduced a bug by wrongly using the `assert_debug_log` helper.
Instead of passing the expected debug string in a list as expected, it
was passed as bare string, which is then interpretered as a list of
characters, very likely leading the debug log assertion pass even if the
intended message is not appearing.

In order to avoid bugs like this in the future, enforce that the
`{un}expected_msgs` parameters are lists.
    ac4caf3366
  13. theStack force-pushed on Oct 13, 2023
  14. theStack commented at 10:44 AM on October 13, 2023: contributor

    Rebased on master and tackled #28645 (review).

  15. DrahtBot removed the label Needs rebase on Oct 13, 2023
  16. DrahtBot added the label Tests on Oct 13, 2023
  17. dergoegge approved
  18. dergoegge commented at 1:42 PM on October 13, 2023: member

    ACK ac4caf3366a85617641394a97aa9f029550d77d4

  19. DrahtBot requested review from jonatack on Oct 13, 2023
  20. achow101 commented at 4:24 PM on October 13, 2023: member

    ACK ac4caf3366a85617641394a97aa9f029550d77d4

  21. maflcko commented at 4:25 PM on October 13, 2023: member

    lgtm ACK ac4caf3366a85617641394a97aa9f029550d77d4

  22. achow101 merged this on Oct 13, 2023
  23. achow101 closed this on Oct 13, 2023
  24. theStack deleted the branch on Oct 13, 2023
  25. Frank-GER referenced this in commit 5629efd2d6 on Oct 21, 2023
  26. bitcoin locked this on Oct 12, 2024
Contributors
theStackDrahtBotfanquakejonatackwillcl-arkmaflckodergoeggeachow101


jonatack

Labels
Tests

Milestone
26.0

Linked (view graph)
#28625 test: check that loading snapshot not matching AssumeUTXO parameters fails#28634 test: BIP324: add check for detection of missing garbage terminator#28639 refactor: Remove unused nchaintx from SnapshotMetadata constructor, fix test, add test
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-14 21:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me