qa: `feature_assumeutxo.py` fails

hebasto commented at 2:18 pm on October 4, 2023: member

https://github.com/bitcoin/bitcoin/actions/runs/6406365281/job/17390816303:

 0284/284 - feature_assumeutxo.py failed, Duration: 2403 s
 1
 2stdout:
 32023-10-04T13:29:47.691000Z TestFramework (INFO): PRNG seed is: 7592694052297737658
 42023-10-04T13:29:47.692000Z TestFramework (INFO): Initializing test directory /Users/runner/work/bitcoin/bitcoin/ci/scratch/test_runner/test_runner_₿_🏃_20231004_132534/feature_assumeutxo_47
 52023-10-04T13:29:49.351000Z TestFramework (INFO): -- Testing assumeutxo + some indexes + pruning
 62023-10-04T13:29:49.355000Z TestFramework (INFO): Creating a UTXO snapshot at height 299
 72023-10-04T13:29:49.794000Z TestFramework (INFO): Loading snapshot into second node from /Users/runner/work/bitcoin/bitcoin/ci/scratch/test_runner/test_runner_₿_🏃_20231004_132534/feature_assumeutxo_47/node0/regtest/utxos.dat
 82023-10-04T13:29:49.908000Z TestFramework (INFO): Restarting node to stop at height 359
 92023-10-04T14:09:50.767000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
10        self.wait_until(lambda: sum(peer['version'] != 0 for peer in from_connection.getpeerinfo()) == from_num_peers)
11'''
122023-10-04T14:09:50.771000Z TestFramework (ERROR): Assertion failed
13Traceback (most recent call last):
14  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_framework.py", line 131, in main
15    self.run_test()
16  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/feature_assumeutxo.py", line 145, in run_test
17    self.connect_nodes(0, 1)
18  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_framework.py", line 611, in connect_nodes
19    self.wait_until(lambda: sum(peer['version'] != 0 for peer in from_connection.getpeerinfo()) == from_num_peers)
20  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_framework.py", line 740, in wait_until
21    return wait_until_helper(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor)
22           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
23  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/util.py", line 276, in wait_until_helper
24    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
25AssertionError: Predicate ''''
26        self.wait_until(lambda: sum(peer['version'] != 0 for peer in from_connection.getpeerinfo()) == from_num_peers)
27''' not true after 2400.0 seconds
282023-10-04T14:09:50.855000Z TestFramework (INFO): Stopping nodes
29[node 2] Cleaning up leftover process
30[node 1] Cleaning up leftover process
31[node 0] Cleaning up leftover process
32
33
34stderr:
35Traceback (most recent call last):
36  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/feature_assumeutxo.py", line 246, in <module>
37    AssumeutxoTest().main()
38  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_framework.py", line 154, in main
39    exit_code = self.shutdown()
40                ^^^^^^^^^^^^^^^
41  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_framework.py", line 313, in shutdown
42    self.stop_nodes()
43  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_framework.py", line 575, in stop_nodes
44    node.stop_node(wait=wait, wait_until_stopped=False)
45  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_node.py", line 357, in stop_node
46    self.stop(wait=wait)
47  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/coverage.py", line 50, in __call__
48    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
49                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
50  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/authproxy.py", line 127, in __call__
51    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
52                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
53  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/authproxy.py", line 105, in _request
54    self.__conn.request(method, path, postdata, headers)
55  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1286, in request
56    self._send_request(method, url, body, headers, encode_chunked)
57  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1332, in _send_request
58    self.endheaders(body, encode_chunked=encode_chunked)
59  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1281, in endheaders
60    self._send_output(message_body, encode_chunked=encode_chunked)
61  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1041, in _send_output
62    self.send(msg)
63  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1002, in send
64    self.sock.sendall(data)
65BrokenPipeError: [Errno 32] Broken pipe

hebasto commented at 2:18 pm on October 4, 2023: member

cc @jamesob

maflcko commented at 2:25 pm on October 4, 2023: member

@fjahr Maybe it could make sense to split out the test fix into a separate pull to avoid a delay in merging the bugfix?

maflcko added the label Tests on Oct 4, 2023

jamesob commented at 2:34 pm on October 4, 2023: member

Hm, I thought this was a timeout issue but 2400 seconds is a really long time! Maybe there’s a more fundamental issue here?

fjahr commented at 2:38 pm on October 4, 2023: contributor

@fjahr Maybe it could make sense to split out the test fix into a separate pull to avoid a delay in merging the bugfix?

Sure, done at #28586 . Please let me know what you think about the default timeout idea, otherwise, I will simply hardcode the timeout value for now.

maflcko commented at 2:46 pm on October 4, 2023: member

Hm, I thought this was a timeout issue but 2400 seconds is a really long time! Maybe there’s a more fundamental issue here?

Yeah, it is not possible to use -stopatheight= and then assume the node does not stop

jamesob commented at 2:58 pm on October 4, 2023: member

Yeah, it is not possible to use -stopatheight= and then assume the node does not stop

But, at least when I wrote the test, the node being restarted (n1) with the -stopatheight= configuration shouldn’t have enough blocks to actually trip that stopatheight until it is connected to a peer with the blocks necessary (node0). I think this is a deeper issue with race between the contents of connect_nodes and the use of -stopatheight.

jamesob commented at 3:13 pm on October 4, 2023: member

Running in a loop locally, I’m detecting another race:

 02023-10-04T15:13:33.740000Z TestFramework (INFO): PRNG seed is: 4294214471523398112
 12023-10-04T15:13:33.741000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_3iqhon05
 22023-10-04T15:13:34.187000Z TestFramework (INFO): -- Testing assumeutxo + some indexes + pruning
 32023-10-04T15:13:34.187000Z TestFramework (INFO): Creating a UTXO snapshot at height 299
 42023-10-04T15:13:34.237000Z TestFramework (INFO): Loading snapshot into second node from /tmp/bitcoin_func_test_3iqhon05/node0/regtest/utxos.dat
 52023-10-04T15:13:34.240000Z TestFramework (INFO): Restarting node to stop at height 359
 62023-10-04T15:13:34.693000Z TestFramework (INFO): Checking that blocks are segmented on disk
 72023-10-04T15:13:34.693000Z TestFramework (INFO): Restarted node before snapshot validation completed, reloading...
 82023-10-04T15:13:34.999000Z TestFramework (INFO): Ensuring snapshot chain syncs to tip. (399)
 92023-10-04T15:13:35.050000Z TestFramework (ERROR): Key error
10Traceback (most recent call last):
11  File "/home/james/src/bitcoin/test/functional/test_framework/test_framework.py", line 131, in main
12    self.run_test()
13  File "/home/james/src/bitcoin/./test/functional/feature_assumeutxo.py", line 162, in run_test
14    wait_until_helper(lambda: n1.getchainstates()['snapshot']['blocks'] == FINAL_HEIGHT)
15  File "/home/james/src/bitcoin/test/functional/test_framework/util.py", line 265, in wait_until_helper
16    if predicate():
17       ^^^^^^^^^^^
18  File "/home/james/src/bitcoin/./test/functional/feature_assumeutxo.py", line 162, in <lambda>
19    wait_until_helper(lambda: n1.getchainstates()['snapshot']['blocks'] == FINAL_HEIGHT)
20                              ~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^
21KeyError: 'snapshot'
222023-10-04T15:13:35.100000Z TestFramework (INFO): Stopping nodes

Investigating…

jamesob commented at 3:20 pm on October 4, 2023: member

Investigating…

Okay, pushed a fix for that as well to #28589 (https://github.com/bitcoin/bitcoin/pull/28589/commits/eae98ccef53eecf678a76adb5f26e87200d7c34d).

achow101 closed this on Oct 4, 2023

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

Julio-Rats referenced this in commit cc68a3b9dd on Jan 26, 2024

bitcoin locked this on Oct 3, 2024

qa: feature_assumeutxo.py fails #28585

qa: `feature_assumeutxo.py` fails #28585