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

theStack · 2023-10-12T15:50:20Z

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

bitcoin/test/functional/feature_assumeutxo.py

Lines 84 to 85 in 5ea4fc0

    
           expected_log = f"assumeutxo height in snapshot metadata not recognized ({bad_snapshot_height}) - refusing to load snapshot" 
        
           with self.nodes[1].assert_debug_log(expected_log):

(already fixed in #28639)

bitcoin/test/functional/p2p_v2_transport.py

Line 148 in 5ea4fc0

    
           with self.nodes[0].assert_debug_log("V2 transport error: V1 peer with wrong MessageStart"):

bitcoin/test/functional/p2p_v2_transport.py

Line 159 in 5ea4fc0

    
           with self.nodes[0].assert_debug_log("V2 transport error: missing garbage terminator"):

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 (comment)

In order to avoid bugs like this in the future, enforce that the {un}expected_msgs parameters are lists, as discussed in #28625 (comment). 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.

theStack · 2023-10-12T15:54:09Z

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'>)

DrahtBot · 2023-10-12T15:54:12Z

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

Code Coverage

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

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.

test/functional/feature_assumeutxo.py

jonatack

ACK 616c090

(If the CI passes. Did it run?)

test/functional/test_framework/test_node.py

maflcko · 2023-10-13T09:17:55Z

(If the CI passes. Did it run?)

Needs rebase, due to GitHub downtime, I guess?

Two recently added tests (PR bitcoin#28625 / commit 2e31250 and PR bitcoin#28634 / commit 3bb51c2) 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.

theStack · 2023-10-13T10:44:04Z

Rebased on master and tackled #28645 (comment).

dergoegge

ACK ac4caf3

achow101 · 2023-10-13T16:24:40Z

ACK ac4caf3

maflcko · 2023-10-13T16:25:40Z

lgtm ACK ac4caf3

… type checks ac4caf3 test: fix `assert_debug_log` call-site bugs, add type checks (Sebastian Falbesoner) Pull request description: Two recently added tests (PR bitcoin#28625 / commit 2e31250 and PR bitcoin#28634 / commit 3bb51c2) 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 bitcoin#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: bitcoin#28625 (comment) In order to avoid bugs like this in the future, enforce that the `{un}expected_msgs` parameters are lists, as discussed in bitcoin#28625 (comment). 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. ACKs for top commit: achow101: ACK ac4caf3 maflcko: lgtm ACK ac4caf3 dergoegge: ACK ac4caf3 Tree-SHA512: a9677af76a0c370e71f0411339807b1dc6b2a81763db4ec049cd6d766404b916e2bdd002883db5a79c9c388d7d8ebfcbd5f31d43d50be868eeb928e3c906a746

fanquake reviewed Oct 12, 2023

View reviewed changes

test/functional/feature_assumeutxo.py Outdated Show resolved Hide resolved

jonatack reviewed Oct 12, 2023

View reviewed changes

test/functional/test_framework/test_node.py Show resolved Hide resolved

maflcko closed this Oct 13, 2023

maflcko reopened this Oct 13, 2023

maflcko added this to the 26.0 milestone Oct 13, 2023

maflcko added the Needs rebase label Oct 13, 2023

theStack force-pushed the 202310-test-enforce_assert_debug_log_list_params branch from 616c090 to ac4caf3 Compare October 13, 2023 10:43

DrahtBot added Tests and removed Needs rebase labels Oct 13, 2023

dergoegge approved these changes Oct 13, 2023

View reviewed changes

DrahtBot requested a review from jonatack October 13, 2023 13:42

achow101 merged commit 78b7e95 into bitcoin:master Oct 13, 2023

theStack deleted the 202310-test-enforce_assert_debug_log_list_params branch October 13, 2023 16:42

bitcoin locked and limited conversation to collaborators Oct 12, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

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

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

Uh oh!

theStack commented Oct 12, 2023 •

edited

Loading

Uh oh!

theStack commented Oct 12, 2023

Uh oh!

DrahtBot commented Oct 12, 2023 •

edited

Loading

Uh oh!

Uh oh!

jonatack left a comment

Uh oh!

Uh oh!

maflcko commented Oct 13, 2023

Uh oh!

theStack commented Oct 13, 2023

Uh oh!

dergoegge left a comment

Uh oh!

achow101 commented Oct 13, 2023

Uh oh!

maflcko commented Oct 13, 2023

Uh oh!

Uh oh!

	expected_log = f"assumeutxo height in snapshot metadata not recognized ({bad_snapshot_height}) - refusing to load snapshot"
	with self.nodes[1].assert_debug_log(expected_log):

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

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

Uh oh!

Conversation

theStack commented Oct 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

theStack commented Oct 12, 2023

Uh oh!

DrahtBot commented Oct 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Code Coverage

Reviews

Uh oh!

Uh oh!

jonatack left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

maflcko commented Oct 13, 2023

Uh oh!

theStack commented Oct 13, 2023

Uh oh!

dergoegge left a comment

Choose a reason for hiding this comment

Uh oh!

achow101 commented Oct 13, 2023

Uh oh!

maflcko commented Oct 13, 2023

Uh oh!

Uh oh!

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

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

theStack commented Oct 12, 2023 •

edited

Loading

DrahtBot commented Oct 12, 2023 •

edited

Loading