test: assumeutxo func test race fixes #28589

jamesob commented at 3:05 PM on October 4, 2023: member

Fixes #28585.

Fixes a few races within the assumeutxo tests:

In general, -stopatheight can't be used with connect_nodes safely because the latter performs blocking assertions that are racy with the stopatheight triggering.
Now that the snapshot chainstate is listed as normal after background validation, accept the final height from either chainstate.

test: add wait_for_connect to BitcoinTestFramework.connect_nodes 7005a01c19

test: assumeutxo: avoid race in functional test 5bd2010f02

DrahtBot commented at 3:05 PM on October 4, 2023: contributor

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

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	MarcoFalke, ryanofsky, fjahr, achow101
Concept ACK	hebasto

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

jamesob renamed this:
~~2023 10 au test fix~~
assumeutxo -stopatheight func test fix
on Oct 4, 2023

fanquake renamed this:
~~assumeutxo -stopatheight func test fix~~
test: assumeutxo -stopatheight func test fix
on Oct 4, 2023

DrahtBot added the label Tests on Oct 4, 2023

fjahr commented at 3:09 PM on October 4, 2023: contributor

Code review ACK 5bd2010f024b5bcccf1d57bae6fc36c53f5facc5

I had just written the same fix essentially. The stopatheight node shuts down before the list of wait_until checks in connect_nodes succeeds. I guess in the python execution is slower in CI but the node and sync is still comparatively fast.

jamesob renamed this:
~~test: assumeutxo -stopatheight func test fix~~
test: assumeutxo func test race fixes
on Oct 4, 2023

in test/functional/feature_assumeutxo.py:134 in eae98ccef5 outdated

 129 | @@ -130,8 +130,8 @@ def no_sync():
 130 |  
 131 |          monitor = n1.getchainstates()
 132 |          assert_equal(monitor['normal']['blocks'], START_HEIGHT)
 133 | -        assert_equal(monitor['snapshot']['blocks'], SNAPSHOT_BASE_HEIGHT)
 134 | -        assert_equal(monitor['snapshot']['snapshot_blockhash'], dump_output['base_hash'])
 135 | +        assert_equal(monitor.get('snapshot', {}).get('blocks'), SNAPSHOT_BASE_HEIGHT)
 136 | +        assert_equal(monitor.get('snapshot', {}).get('snapshot_blockhash'), dump_output['base_hash'])

maflcko commented at 3:20 PM on October 4, 2023:

not sure. What is the goal of those changes, other than making the code more verbose and harder to read?

jamesob commented at 3:21 PM on October 4, 2023:

snapshot is an optional key in the RPC's return value, so if the above call returns before a snapshot chainstate is loaded, it will KeyError as I've shown in #28585.

jamesob commented at 3:23 PM on October 4, 2023:

Oh I see what you're saying - the test will still fail; of course... Reverting those.

maflcko commented at 3:24 PM on October 4, 2023:

But then the assert_equal will fail anyway later on, no?

hebasto commented at 3:25 PM on October 4, 2023: member

Concept ACK.

maflcko commented at 3:26 PM on October 4, 2023: member

lgtm ACK 5bd2010f024b5bcccf1d57bae6fc36c53f5facc5

jamesob force-pushed on Oct 4, 2023

jamesob commented at 3:28 PM on October 4, 2023: member

Even with latest HEAD, still seeing an apparent race. Still investigating.

2023-10-04T15:24:47.476000Z TestFramework (INFO): Restarted node before snapshot validation completed, reloading...
2023-10-04T15:24:47.782000Z TestFramework (INFO): Ensuring snapshot chain syncs to tip. (399)
2023-10-04T15:25:47.828000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
            lambda: n1.getchainstates().get('snapshot', {}).get('blocks') == FINAL_HEIGHT)
'''
2023-10-04T15:25:47.828000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/james/src/bitcoin/test/functional/test_framework/test_framework.py", line 131, in main
    self.run_test()
  File "/home/james/src/bitcoin/./test/functional/feature_assumeutxo.py", line 162, in run_test
    wait_until_helper(
  File "/home/james/src/bitcoin/test/functional/test_framework/util.py", line 276, in wait_until_helper
    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
AssertionError: Predicate ''''
            lambda: n1.getchainstates().get('snapshot', {}).get('blocks') == FINAL_HEIGHT)
''' not true after 60.0 seconds
2023-10-04T15:25:47.879000Z TestFramework (INFO): Stopping nodes

jamesob force-pushed on Oct 4, 2023

tests: assumeutxo: accept final height from either chainstate 7e40032260

maflcko commented at 3:34 PM on October 4, 2023: member

lgtm ACK 7e4003226030a04a19c718a4b1b83b4ca40ca33f

DrahtBot requested review from fjahr on Oct 4, 2023

jamesob commented at 3:35 PM on October 4, 2023: member

Alright, I'm guessing we're fixed for real this time; https://github.com/bitcoin/bitcoin/pull/28589/commits/7e4003226030a04a19c718a4b1b83b4ca40ca33f accounts for the late change that we made on @ryanofsky's recommendation to list what was the snapshot chainstate as the normal chainstate once background validation completes. There was a race in the test during the first time we check for the final height, which may be done after background validation completed.

I'm going to keep running the test in a loop on my end and will post back in a bit to confirm that I think we're good to go.

fanquake added this to the milestone 26.0 on Oct 4, 2023

ryanofsky approved

ryanofsky commented at 3:52 PM on October 4, 2023: contributor

Code review ACK 7e4003226030a04a19c718a4b1b83b4ca40ca33f

(#28590 would allow simplifying the check in 7e4003226030a04a19c718a4b1b83b4ca40ca33f as well)

fjahr commented at 3:54 PM on October 4, 2023: contributor

Code review ACK 7e4003226030a04a19c718a4b1b83b4ca40ca33f

DrahtBot removed review request from fjahr on Oct 4, 2023

achow101 commented at 4:19 PM on October 4, 2023: member

ACK 7e4003226030a04a19c718a4b1b83b4ca40ca33f

Gonna let this run in a loop for a bit before merging.

DrahtBot requested review from achow101 on Oct 4, 2023

DrahtBot removed review request from achow101 on Oct 4, 2023

jamesob commented at 4:57 PM on October 4, 2023: member

Test has been running on my machine in a loop without failure for about an hour now.

achow101 merged this on Oct 4, 2023

achow101 closed this on Oct 4, 2023

Frank-GER referenced this in commit af0ee8b2a3 on Oct 13, 2023

bitcoin locked this on Oct 3, 2024