Post startup stalling #29281

issue fanquake opened this issue on January 19, 2024

fanquake commented at 9:50 AM on January 19, 2024: member

Noticed this on a node recently. Basically startup, sync two blocks, but then stall for 15 minutes, until we timed out a peer (in this case a blocks-only peer). @mzumsande mentioned this is because we were too close to tip, for the stalling logic to kick in, but also not close enough for the parallel download logic to kick in. I'm wondering if we should adjust the thresholds for either, to try and make this less likely to occur. It's possible this is also the same issue being seen here: #12291 (comment).

2024-01-17T21:04:16.142907Z [init] Initializing chainstate Chainstate [ibd] @ height -1 (null)
2024-01-17T21:04:16.143281Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/chainstate
2024-01-17T21:04:17.980716Z [init] Opened LevelDB successfully
2024-01-17T21:04:17.981318Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/chainstate: 77d7aeef08b2778d
2024-01-17T21:04:18.522369Z [init] Loaded best chain: hashBestChain=00000000000000000000e21c52f32e7b4695ce0b8e8bb57e579b186d0c398dcf height=825926 date=2024-01-15T21:11:05Z progress=0.999002
2024-01-17T21:04:18.562453Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/chainstate
2024-01-17T21:04:18.696457Z [init] Opened LevelDB successfully
2024-01-17T21:04:18.696688Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/chainstate: 77d7aeef08b2778d
2024-01-17T21:04:18.696755Z [init] [Chainstate [ibd] @ height 825926 (00000000000000000000e21c52f32e7b4695ce0b8e8bb57e579b186d0c398dcf)] resized coinsdb cache to 8.0 MiB
2024-01-17T21:04:18.696797Z [init] [Chainstate [ibd] @ height 825926 (00000000000000000000e21c52f32e7b4695ce0b8e8bb57e579b186d0c398dcf)] resized coinstip cache to 384.0 MiB
2024-01-17T21:04:18.696894Z [init] init message: Verifying blocks…
2024-01-17T21:04:18.696973Z [init] Verifying last 6 blocks at level 3
2024-01-17T21:04:18.697061Z [init] Verification progress: 0%
2024-01-17T21:04:24.319192Z [init] Verification progress: 16%
2024-01-17T21:04:29.624412Z [init] Verification progress: 33%
2024-01-17T21:04:32.856466Z [init] Verification progress: 50%
2024-01-17T21:04:34.598393Z [init] Verification progress: 66%
2024-01-17T21:04:36.152079Z [init] Verification progress: 83%
2024-01-17T21:04:37.727802Z [init] Verification progress: 99%
2024-01-17T21:04:37.727970Z [init] Verification: No coin database inconsistencies in last 6 blocks (18844 transactions)
2024-01-17T21:04:37.777381Z [init]  block index           57277ms
2024-01-17T21:04:37.785599Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/indexes/blockfilter/basic/db
2024-01-17T21:04:37.812648Z [init] Opened LevelDB successfully
2024-01-17T21:04:37.812778Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/indexes/blockfilter/basic/db: 0000000000000000
2024-01-17T21:04:37.813033Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/indexes/coinstats/db
2024-01-17T21:04:37.852950Z [init] Opened LevelDB successfully
2024-01-17T21:04:37.853086Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/indexes/coinstats/db: 0000000000000000
2024-01-17T21:04:37.930277Z [init] init message: Pruning blockstore…
2024-01-17T21:04:37.930708Z [init] block tree size = 825941
2024-01-17T21:04:37.930757Z [init] nBestHeight = 825926
2024-01-17T21:04:37.930832Z [initload] initload thread start
2024-01-17T21:04:37.931027Z [torcontrol] torcontrol thread start
2024-01-17T21:04:37.931121Z [coinstatsindex] coinstatsindex thread start
2024-01-17T21:04:37.931225Z [basic block filter index] basic block filter index thread start
2024-01-17T21:04:37.931332Z [coinstatsindex] coinstatsindex is enabled at height 825926
2024-01-17T21:04:37.931386Z [coinstatsindex] coinstatsindex thread exit
2024-01-17T21:04:37.931431Z [basic block filter index] basic block filter index is enabled at height 825926
2024-01-17T21:04:37.931493Z [basic block filter index] basic block filter index thread exit
2024-01-17T21:04:37.931545Z [init] Bound to 127.0.0.1:8334
2024-01-17T21:04:37.931692Z [init] Bound to [::]:8333
2024-01-17T21:04:37.931830Z [init] Bound to 0.0.0.0:8333
2024-01-17T21:04:37.933190Z [initload] Loading 19467 mempool transactions from disk...
2024-01-17T21:04:37.933335Z [init] Loaded 2 addresses from "anchors.dat"
2024-01-17T21:04:37.934342Z [init] 2 block-relay-only anchors will be tried for connections.
2024-01-17T21:04:37.934441Z [init] init message: Starting network threads…
2024-01-17T21:04:37.934636Z [net] net thread start
2024-01-17T21:04:37.934726Z [dnsseed] dnsseed thread start
2024-01-17T21:04:37.934844Z [addcon] addcon thread start
2024-01-17T21:04:37.934962Z [opencon] opencon thread start
2024-01-17T21:04:37.935037Z [msghand] msghand thread start
2024-01-17T21:04:37.935118Z [dnsseed] Waiting 300 seconds before querying DNS seeds.
2024-01-17T21:04:37.935608Z [init] init message: Done loading
2024-01-17T21:04:44.720652Z [msghand] New block-relay-only v1 peer connected: version: 70016, blocks=826175, peer=0, peeraddr=24.118.251.111:8333
2024-01-17T21:04:45.088087Z [msghand] Synchronizing blockheaders, height: 826175 (~100.00%)
2024-01-17T21:04:45.298560Z [msghand] New outbound-full-relay v1 peer connected: version: 70016, blocks=826175, peer=2, peeraddr=213.144.146.33:8333
2024-01-17T21:04:46.518049Z [initload] Progress loading mempool transactions from disk: 10% (tried 1947, 17520 remaining)
2024-01-17T21:04:50.041449Z [msghand] UpdateTip: new best=00000000000000000000ff10e27886dcbad5e3f737aea821dd0bfca23a29222e height=825927 version=0x34870000 log2_work=94.668428 tx=952738179 date='2024-01-15T21:27:43Z' progress=0.999007 cache=2.9MiB(22933txo)
2024-01-17T21:04:53.647945Z [msghand] UpdateTip: new best=0000000000000000000231eb8884fec2e3c2fe14fd82626bcaa1a7ceec5caf93 height=825928 version=0x24b24000 log2_work=94.668442 tx=952741302 date='2024-01-15T21:34:01Z' progress=0.999010 cache=4.8MiB(36259txo)
2024-01-17T21:05:18.323365Z [msghand] New outbound-full-relay v1 peer connected: version: 70015, blocks=826175, peer=6, peeraddr=221.223.27.170:2011
2024-01-17T21:05:20.186948Z [msghand] New outbound-full-relay v1 peer connected: version: 70015, blocks=826175, peer=9, peeraddr=31.171.251.35:8333
2024-01-17T21:05:21.948231Z [dnsseed] P2P peers available. Skipped DNS seeding.
2024-01-17T21:05:21.948340Z [dnsseed] dnsseed thread exit
2024-01-17T21:05:38.095382Z [msghand] New outbound-full-relay v1 peer connected: version: 70016, blocks=826175, peer=11, peeraddr=159.89.121.240:8333
2024-01-17T21:05:40.146740Z [msghand] New outbound-full-relay v1 peer connected: version: 70016, blocks=826175, peer=13, peeraddr=66.203.112.31:30034
2024-01-17T21:05:42.838455Z [msghand] New outbound-full-relay v1 peer connected: version: 70016, blocks=826175, peer=16, peeraddr=104.189.105.88:8333
2024-01-17T21:05:42.839679Z [msghand] New outbound-full-relay v1 peer connected: version: 70016, blocks=826175, peer=14, peeraddr=93.57.81.162:8333
2024-01-17T21:05:43.871172Z [msghand] New outbound-full-relay v1 peer connected: version: 70016, blocks=826175, peer=15, peeraddr=192.146.137.44:8333
2024-01-17T21:05:48.566843Z [msghand] New outbound-full-relay v1 peer connected: version: 70015, blocks=826175, peer=19, peeraddr=91.147.232.98:8333
2024-01-17T21:06:01.649709Z [initload] Progress loading mempool transactions from disk: 20% (tried 3894, 15573 remaining)
2024-01-17T21:06:24.172283Z [msghand] New outbound-full-relay v1 peer connected: version: 70016, blocks=826175, peer=22, peeraddr=108.214.8.13:50501
2024-01-17T21:06:33.410186Z [initload] Progress loading mempool transactions from disk: 30% (tried 5841, 13626 remaining)
2024-01-17T21:06:49.051526Z [msghand] New block-relay-only v1 peer connected: version: 70015, blocks=826175, peer=23, peeraddr=34.95.0.69:8333
2024-01-17T21:07:24.909070Z [msghand] Synchronizing blockheaders, height: 826176 (~100.00%)
2024-01-17T21:07:43.039910Z [msghand] New block-relay-only v1 peer connected: version: 70016, blocks=826176, peer=25, peeraddr=198.58.118.99:8333
2024-01-17T21:08:29.431947Z [initload] Progress loading mempool transactions from disk: 40% (tried 7787, 11680 remaining)
2024-01-17T21:11:05.226379Z [initload] Progress loading mempool transactions from disk: 50% (tried 9734, 9733 remaining)
2024-01-17T21:13:32.216591Z [initload] Progress loading mempool transactions from disk: 60% (tried 11681, 7786 remaining)
2024-01-17T21:14:03.498201Z [msghand] Synchronizing blockheaders, height: 826177 (~100.00%)
2024-01-17T21:14:45.905189Z [initload] Progress loading mempool transactions from disk: 70% (tried 13627, 5840 remaining)
2024-01-17T21:15:14.282892Z [initload] Progress loading mempool transactions from disk: 80% (tried 15574, 3893 remaining)
2024-01-17T21:15:31.923806Z [initload] Progress loading mempool transactions from disk: 90% (tried 17521, 1946 remaining)
2024-01-17T21:15:35.950446Z [initload] Imported mempool transactions from disk: 19358 succeeded, 109 failed, 0 expired, 0 already there, 0 waiting for initial broadcast
2024-01-17T21:15:35.950530Z [initload] initload thread exit
2024-01-17T21:18:46.843126Z [msghand] Synchronizing blockheaders, height: 826178 (~100.00%)
2024-01-17T21:19:51.712211Z [msghand] Timeout downloading block 0000000000000000000388f339429b7cdb2b9d50cf7482dea9556afdc2033d17 from peer=0 peeraddr=24.118.251.111:8333, disconnecting
2024-01-17T21:19:51.944570Z [msghand] New block-relay-only v1 peer connected: version: 70016, blocks=826178, peer=26, peeraddr=86.89.51.161:8333
2024-01-17T21:19:52.960361Z [msghand] New block-relay-only v1 peer connected: version: 70016, blocks=826178, peer=27, peeraddr=82.192.82.173:8333
2024-01-17T21:19:57.559635Z [msghand] UpdateTip: new best=0000000000000000000388f339429b7cdb2b9d50cf7482dea9556afdc2033d17 height=825929 version=0x32f88000 log2_work=94.668457 tx=952745617 date='2024-01-15T21:48:17Z' progress=0.999009 cache=78.2MiB(662424txo)

fanquake added the label P2P on Jan 19, 2024
sipa commented at 12:32 PM on January 19, 2024: member

Discussed this briefly with @mzumsande.

The stalling detection logic is ineffective here, because that only triggers when the 1024-block wide download window cannot move, and as you're less than 1024 blocks behind, the window is already as far as it can go.

We should probably have a separate criterion for stalling detection in this case.
mzumsande commented at 3:50 PM on January 19, 2024: contributor

Another question is how to deal with it after having a separate detection criterion. The stalling logic is designed such that if we are in a situation where other peers are blocked by the staller, the staller will be disconnected (hopefully downloading the missing block from someone else and unblocking the other peers with unused download slots). In the situation here, there is probably no other peer blocked; we just want to get to the tip faster, rather than waiting for 10+ minutes (BLOCK_DOWNLOAD_TIMEOUT_BASE). This makes me think it might be more logical to request the block from a second peer more quickly. The groundwork for this (changes to mapBlocksInFlight) is already in place thanks to #27626, which implemented it for compact blocks.
mzumsande commented at 9:35 PM on March 11, 2024: contributor

I'm working on a solution for this, will hopefully open a PR in the next couple of days.
mzumsande commented at 10:28 PM on March 15, 2024: contributor

see #29664

Contributors

Labels

Linked (view graph)

#12291 Timeout downloading block #29664 p2p: When close to the tip, download blocks in parallel from additional peers to prevent stalling