qa: `feature_assumeutxo.py` fails #28585

issue hebasto opened this issue on October 4, 2023
  1. hebasto commented at 2:18 PM on October 4, 2023: member

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

    284/284 - feature_assumeutxo.py failed, Duration: 2403 s

stdout:
2023-10-04T13:29:47.691000Z TestFramework (INFO): PRNG seed is: 7592694052297737658
2023-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
2023-10-04T13:29:49.351000Z TestFramework (INFO): -- Testing assumeutxo + some indexes + pruning
2023-10-04T13:29:49.355000Z TestFramework (INFO): Creating a UTXO snapshot at height 299
2023-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
2023-10-04T13:29:49.908000Z TestFramework (INFO): Restarting node to stop at height 359
2023-10-04T14:09:50.767000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        self.wait_until(lambda: sum(peer['version'] != 0 for peer in from_connection.getpeerinfo()) == from_num_peers)
'''
2023-10-04T14:09:50.771000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  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
    self.run_test()
  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/feature_assumeutxo.py", line 145, in run_test
    self.connect_nodes(0, 1)
  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
    self.wait_until(lambda: sum(peer['version'] != 0 for peer in from_connection.getpeerinfo()) == from_num_peers)
  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
    return wait_until_helper(test_function, timeout=timeout, timeout_factor=self.options.timeout_factor)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  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
    raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
AssertionError: Predicate ''''
        self.wait_until(lambda: sum(peer['version'] != 0 for peer in from_connection.getpeerinfo()) == from_num_peers)
''' not true after 2400.0 seconds
2023-10-04T14:09:50.855000Z TestFramework (INFO): Stopping nodes
[node 2] Cleaning up leftover process
[node 1] Cleaning up leftover process
[node 0] Cleaning up leftover process


stderr:
Traceback (most recent call last):
  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/feature_assumeutxo.py", line 246, in <module>
    AssumeutxoTest().main()
  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
    exit_code = self.shutdown()
                ^^^^^^^^^^^^^^^
  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
    self.stop_nodes()
  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
    node.stop_node(wait=wait, wait_until_stopped=False)
  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
    self.stop(wait=wait)
  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/coverage.py", line 50, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/authproxy.py", line 127, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/authproxy.py", line 105, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1286, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1332, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1281, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1041, in _send_output
    self.send(msg)
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 1002, in send
    self.sock.sendall(data)
BrokenPipeError: [Errno 32] Broken pipe
  2. hebasto commented at 2:18 PM on October 4, 2023: member

    cc @jamesob

  3. 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?

  4. maflcko added the label Tests on Oct 4, 2023
  5. 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?

  6. 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.

  7. 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

  8. 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.

  9. jamesob commented at 3:13 PM on October 4, 2023: member

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

    2023-10-04T15:13:33.740000Z TestFramework (INFO): PRNG seed is: 4294214471523398112
2023-10-04T15:13:33.741000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_3iqhon05
2023-10-04T15:13:34.187000Z TestFramework (INFO): -- Testing assumeutxo + some indexes + pruning
2023-10-04T15:13:34.187000Z TestFramework (INFO): Creating a UTXO snapshot at height 299
2023-10-04T15:13:34.237000Z TestFramework (INFO): Loading snapshot into second node from /tmp/bitcoin_func_test_3iqhon05/node0/regtest/utxos.dat
2023-10-04T15:13:34.240000Z TestFramework (INFO): Restarting node to stop at height 359
2023-10-04T15:13:34.693000Z TestFramework (INFO): Checking that blocks are segmented on disk
2023-10-04T15:13:34.693000Z TestFramework (INFO): Restarted node before snapshot validation completed, reloading...
2023-10-04T15:13:34.999000Z TestFramework (INFO): Ensuring snapshot chain syncs to tip. (399)
2023-10-04T15:13:35.050000Z TestFramework (ERROR): Key error
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(lambda: n1.getchainstates()['snapshot']['blocks'] == FINAL_HEIGHT)
  File "/home/james/src/bitcoin/test/functional/test_framework/util.py", line 265, in wait_until_helper
    if predicate():
       ^^^^^^^^^^^
  File "/home/james/src/bitcoin/./test/functional/feature_assumeutxo.py", line 162, in <lambda>
    wait_until_helper(lambda: n1.getchainstates()['snapshot']['blocks'] == FINAL_HEIGHT)
                              ~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^
KeyError: 'snapshot'
2023-10-04T15:13:35.100000Z TestFramework (INFO): Stopping nodes

    Investigating...

  10. 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).

  11. achow101 closed this on Oct 4, 2023
  12. Frank-GER referenced this in commit af0ee8b2a3 on Oct 13, 2023
  13. Julio-Rats referenced this in commit cc68a3b9dd on Jan 26, 2024
  14. bitcoin locked this on Oct 3, 2024
Contributors
hebastomaflckojamesobfjahr
Labels
Tests
Linked (view graph)
#28589 test: assumeutxo func test race fixes
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-05-02 15:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me