Page MenuHomePhabricator

assumeUTXO: fix peers disconnection during sync
Changes PlannedPublic

Authored by PiRK on Tue, Apr 22, 13:33.

Details

Reviewers
None
Group Reviewers
Restricted Project
Summary

Because AssumeUTXO nodes prioritize tip synchronization, they relay their local
address through the network before completing the background chain sync.
This, combined with the advertising of full-node service (NODE_NETWORK), can
result in an honest peer in IBD connecting to the AssumeUTXO node (while syncing)
and requesting an historical block the node does not have. This behavior leads to
an abrupt disconnection due to perceived unresponsiveness (lack of response)
from the AssumeUTXO node.

This lack of response occurs because nodes ignore getdata requests when they do
not have the block data available (further discussion can be found in PR 30385).

Fix this by refraining from signaling full-node service support while the
background chain is being synced. During this period, the node will only
signal 'NODE_NETWORK_LIMITED' support. Then, full-node ('NODE_NETWORK')
support will be re-enabled once the background chain sync is completed.

Add coverage for assumeUTXO honest peers disconnection.

Exercising and verifying the following points:

  1. An IBD node can sync headers from an AssumeUTXO node at any time.
  1. IBD nodes do not request historical blocks from AssumeUTXO nodes while they are syncing the background-chain.
  1. The assumeUTXO node dynamically adjusts the network services it offers according to its state.
  1. IBD nodes can fully sync from AssumeUTXO nodes after they finish the background-chain sync.

This is a backport of core#30807

Depends on D17966

Test Plan

ninja all check-all

Event Timeline

PiRK requested review of this revision.Tue, Apr 22, 13:33

Failed tests logs:

====== Bitcoin ABC functional tests: feature_assumeutxo.py ======

------- Stdout: -------
2025-04-22T13:39:20.770000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_133811/feature_assumeutxo_24
2025-04-22T13:39:24.196000Z TestFramework (INFO): -- Testing assumeutxo + some indexes + pruning
2025-04-22T13:39:24.198000Z TestFramework (INFO): Creating a UTXO snapshot at height 299
2025-04-22T13:39:24.240000Z TestFramework (INFO): Test loading snapshot when headers are not synced
2025-04-22T13:39:29.624000Z TestFramework (INFO): Test bitcoind should fail when mempool not empty.
2025-04-22T13:39:31.606000Z TestFramework (INFO): Test different scenarios of loading invalid snapshot files
2025-04-22T13:39:31.606000Z TestFramework (INFO):   - snapshot file refering to a block that is not in the assumeutxo parameters
2025-04-22T13:39:31.609000Z TestFramework (INFO):   - snapshot file with wrong number of coins
2025-04-22T13:39:31.800000Z TestFramework (INFO):   - snapshot file with alternated UTXO data
2025-04-22T13:39:32.512000Z TestFramework (INFO): Test bitcoind should fail when file path is invalid.
2025-04-22T13:39:32.514000Z TestFramework (INFO): Loading snapshot into second node from /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_133811/feature_assumeutxo_24/node0/regtest/utxos.dat
2025-04-22T13:39:32.721000Z TestFramework (INFO): Confirm that local services remain unchanged
2025-04-22T13:39:32.969000Z TestFramework (INFO): Submit a stale block that forked off the chain before the snapshot
2025-04-22T13:39:32.990000Z TestFramework (INFO): Submit a spending transaction for a snapshot chainstate coin to the mempool
2025-04-22T13:39:33.019000Z TestFramework (INFO): Restarting node to stop at height 359
2025-04-22T13:39:38.656000Z TestFramework (INFO): Checking that blocks are segmented on disk
2025-04-22T13:39:38.657000Z TestFramework (INFO): Restarted node before snapshot validation completed, reloading...
2025-04-22T13:39:41.290000Z TestFramework (INFO): Ensuring snapshot chain syncs to tip. (399)
2025-04-22T13:39:43.075000Z TestFramework (INFO): Ensuring background validation completes
2025-04-22T13:41:47.713000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        self.wait_until(lambda: n1.getindexinfo() == completed_idx_state)
'''
2025-04-22T13:41:47.713000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 152, in main
    self._run_test_internal()
  File "/work/test/functional/test_framework/test_framework.py", line 142, in _run_test_internal
    self.run_test()
  File "/work/test/functional/feature_assumeutxo.py", line 575, in run_test
    self.wait_until(lambda: n1.getindexinfo() == completed_idx_state)
  File "/work/test/functional/test_framework/test_framework.py", line 890, in wait_until
    return wait_until_helper(
           ^^^^^^^^^^^^^^^^^^
  File "/work/test/functional/test_framework/util.py", line 309, in wait_until_helper
    raise AssertionError(
AssertionError: Predicate ''''
        self.wait_until(lambda: n1.getindexinfo() == completed_idx_state)
''' not true after 120.0 seconds
2025-04-22T13:41:47.765000Z TestFramework (INFO): Stopping nodes
2025-04-22T13:41:48.020000Z TestFramework (WARNING): Not cleaning up dir /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_133811/feature_assumeutxo_24
2025-04-22T13:41:48.020000Z TestFramework (ERROR): Test failed. Test logging available at /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_133811/feature_assumeutxo_24/test_framework.log
2025-04-22T13:41:48.020000Z TestFramework (ERROR): 
2025-04-22T13:41:48.021000Z TestFramework (ERROR): Hint: Call /work/test/functional/combine_logs.py '/work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_133811/feature_assumeutxo_24' to consolidate all logs
2025-04-22T13:41:48.021000Z TestFramework (ERROR): 
2025-04-22T13:41:48.021000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-04-22T13:41:48.021000Z TestFramework (ERROR): https://github.com/Bitcoin-ABC/bitcoin-abc/issues
2025-04-22T13:41:48.021000Z TestFramework (ERROR):

Each failure log is accessible here:
Bitcoin ABC functional tests: feature_assumeutxo.py

Failed tests logs:

====== Bitcoin ABC functional tests: feature_assumeutxo.py ======

------- Stdout: -------
2025-04-22T14:38:47.367000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_143738/feature_assumeutxo_24
2025-04-22T14:38:50.575000Z TestFramework (INFO): -- Testing assumeutxo + some indexes + pruning
2025-04-22T14:38:50.577000Z TestFramework (INFO): Creating a UTXO snapshot at height 299
2025-04-22T14:38:50.600000Z TestFramework (INFO): Test loading snapshot when headers are not synced
2025-04-22T14:39:06.908000Z TestFramework (INFO): Test bitcoind should fail when mempool not empty.
2025-04-22T14:39:08.010000Z TestFramework (INFO): Test different scenarios of loading invalid snapshot files
2025-04-22T14:39:08.010000Z TestFramework (INFO):   - snapshot file refering to a block that is not in the assumeutxo parameters
2025-04-22T14:39:08.013000Z TestFramework (INFO):   - snapshot file with wrong number of coins
2025-04-22T14:39:08.073000Z TestFramework (INFO):   - snapshot file with alternated UTXO data
2025-04-22T14:39:08.262000Z TestFramework (INFO): Test bitcoind should fail when file path is invalid.
2025-04-22T14:39:08.265000Z TestFramework (INFO): Loading snapshot into second node from /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_143738/feature_assumeutxo_24/node0/regtest/utxos.dat
2025-04-22T14:39:08.324000Z TestFramework (INFO): Confirm that local services remain unchanged
2025-04-22T14:39:08.514000Z TestFramework (INFO): Submit a stale block that forked off the chain before the snapshot
2025-04-22T14:39:08.528000Z TestFramework (INFO): Submit a spending transaction for a snapshot chainstate coin to the mempool
2025-04-22T14:39:08.562000Z TestFramework (INFO): Restarting node to stop at height 359
2025-04-22T14:39:12.785000Z TestFramework (INFO): Checking that blocks are segmented on disk
2025-04-22T14:39:12.786000Z TestFramework (INFO): Restarted node before snapshot validation completed, reloading...
2025-04-22T14:39:14.220000Z TestFramework (INFO): Ensuring snapshot chain syncs to tip. (399)
2025-04-22T14:39:15.514000Z TestFramework (INFO): Ensuring background validation completes
2025-04-22T14:39:20.277000Z TestFramework (INFO): Re-check nTx and nChainTx values
2025-04-22T14:39:20.498000Z TestFramework (INFO): Restarting node 0 to ensure (Check|Load)BlockIndex passes
2025-04-22T14:39:21.632000Z TestFramework (INFO): Restarting node 1 to ensure (Check|Load)BlockIndex passes
2025-04-22T14:39:22.799000Z TestFramework (INFO): -- Testing all indexes + reindex
2025-04-22T14:39:22.801000Z TestFramework (INFO): Loading snapshot into third node from /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_143738/feature_assumeutxo_24/node0/regtest/utxos.dat
2025-04-22T14:39:22.885000Z TestFramework (INFO): Check node2 updated the local services during snapshot load
2025-04-22T14:39:22.886000Z TestFramework (INFO): Check that restarting with -reindex=1 will delete the snapshot chainstate
2025-04-22T14:39:28.227000Z TestFramework (INFO): Check that restarting with -reindex-chainstate=1 will delete the snapshot chainstate
2025-04-22T14:39:32.632000Z TestFramework (INFO): Check that loading the snapshot again will fail because there is already an active snapshot.
2025-04-22T14:39:40.846000Z TestFramework (INFO): Ensuring background validation completes
2025-04-22T14:39:47.379000Z TestFramework (INFO): Restarting node 0 to ensure (Check|Load)BlockIndex passes
2025-04-22T14:39:48.850000Z TestFramework (INFO): Restarting node 2 to ensure (Check|Load)BlockIndex passes
2025-04-22T14:39:50.739000Z TestFramework (INFO): Test -reindex-chainstate of an assumeutxo-synced node
2025-04-22T14:39:56.845000Z TestFramework (INFO): Test -reindex of an assumeutxo-synced node
2025-04-22T14:40:07.696000Z TestFramework (INFO): Check importing a snapshot where current chain-tip is not an ancestor of the snapshot block but has less work
2025-04-22T14:40:17.981000Z TestFramework (INFO): Testing IBD-sync from assumeUTXO node
2025-04-22T14:40:32.798000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 152, in main
    self._run_test_internal()
  File "/work/test/functional/test_framework/test_framework.py", line 142, in _run_test_internal
    self.run_test()
  File "/work/test/functional/feature_assumeutxo.py", line 707, in run_test
    self.test_sync_from_assumeutxo_node(snapshot=dump_output)
  File "/work/test/functional/feature_assumeutxo.py", line 327, in test_sync_from_assumeutxo_node
    assert "NETWORK" in snapshot_node.getnetworkinfo()["localservicesnames"]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError
2025-04-22T14:40:32.851000Z TestFramework (INFO): Stopping nodes
2025-04-22T14:40:33.005000Z TestFramework (WARNING): Not cleaning up dir /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_143738/feature_assumeutxo_24
2025-04-22T14:40:33.006000Z TestFramework (ERROR): Test failed. Test logging available at /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_143738/feature_assumeutxo_24/test_framework.log
2025-04-22T14:40:33.006000Z TestFramework (ERROR): 
2025-04-22T14:40:33.006000Z TestFramework (ERROR): Hint: Call /work/test/functional/combine_logs.py '/work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_🏃_20250422_143738/feature_assumeutxo_24' to consolidate all logs
2025-04-22T14:40:33.006000Z TestFramework (ERROR): 
2025-04-22T14:40:33.006000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-04-22T14:40:33.006000Z TestFramework (ERROR): https://github.com/Bitcoin-ABC/bitcoin-abc/issues
2025-04-22T14:40:33.006000Z TestFramework (ERROR):

Each failure log is accessible here:
Bitcoin ABC functional tests: feature_assumeutxo.py

PiRK planned changes to this revision.Tue, Apr 22, 15:30