Post startup stalling

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

 02024-01-17T21:04:16.142907Z [init] Initializing chainstate Chainstate [ibd] @ height -1 (null)
 12024-01-17T21:04:16.143281Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/chainstate
 22024-01-17T21:04:17.980716Z [init] Opened LevelDB successfully
 32024-01-17T21:04:17.981318Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/chainstate: 77d7aeef08b2778d
 42024-01-17T21:04:18.522369Z [init] Loaded best chain: hashBestChain=00000000000000000000e21c52f32e7b4695ce0b8e8bb57e579b186d0c398dcf height=825926 date=2024-01-15T21:11:05Z progress=0.999002
 52024-01-17T21:04:18.562453Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/chainstate
 62024-01-17T21:04:18.696457Z [init] Opened LevelDB successfully
 72024-01-17T21:04:18.696688Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/chainstate: 77d7aeef08b2778d
 82024-01-17T21:04:18.696755Z [init] [Chainstate [ibd] @ height 825926 (00000000000000000000e21c52f32e7b4695ce0b8e8bb57e579b186d0c398dcf)] resized coinsdb cache to 8.0 MiB
 92024-01-17T21:04:18.696797Z [init] [Chainstate [ibd] @ height 825926 (00000000000000000000e21c52f32e7b4695ce0b8e8bb57e579b186d0c398dcf)] resized coinstip cache to 384.0 MiB
102024-01-17T21:04:18.696894Z [init] init message: Verifying blocks…
112024-01-17T21:04:18.696973Z [init] Verifying last 6 blocks at level 3
122024-01-17T21:04:18.697061Z [init] Verification progress: 0%
132024-01-17T21:04:24.319192Z [init] Verification progress: 16%
142024-01-17T21:04:29.624412Z [init] Verification progress: 33%
152024-01-17T21:04:32.856466Z [init] Verification progress: 50%
162024-01-17T21:04:34.598393Z [init] Verification progress: 66%
172024-01-17T21:04:36.152079Z [init] Verification progress: 83%
182024-01-17T21:04:37.727802Z [init] Verification progress: 99%
192024-01-17T21:04:37.727970Z [init] Verification: No coin database inconsistencies in last 6 blocks (18844 transactions)
202024-01-17T21:04:37.777381Z [init]  block index           57277ms
212024-01-17T21:04:37.785599Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/indexes/blockfilter/basic/db
222024-01-17T21:04:37.812648Z [init] Opened LevelDB successfully
232024-01-17T21:04:37.812778Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/indexes/blockfilter/basic/db: 0000000000000000
242024-01-17T21:04:37.813033Z [init] Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/indexes/coinstats/db
252024-01-17T21:04:37.852950Z [init] Opened LevelDB successfully
262024-01-17T21:04:37.853086Z [init] Using obfuscation key for /Users/xxx/Library/Application Support/Bitcoin/indexes/coinstats/db: 0000000000000000
272024-01-17T21:04:37.930277Z [init] init message: Pruning blockstore…
282024-01-17T21:04:37.930708Z [init] block tree size = 825941
292024-01-17T21:04:37.930757Z [init] nBestHeight = 825926
302024-01-17T21:04:37.930832Z [initload] initload thread start
312024-01-17T21:04:37.931027Z [torcontrol] torcontrol thread start
322024-01-17T21:04:37.931121Z [coinstatsindex] coinstatsindex thread start
332024-01-17T21:04:37.931225Z [basic block filter index] basic block filter index thread start
342024-01-17T21:04:37.931332Z [coinstatsindex] coinstatsindex is enabled at height 825926
352024-01-17T21:04:37.931386Z [coinstatsindex] coinstatsindex thread exit
362024-01-17T21:04:37.931431Z [basic block filter index] basic block filter index is enabled at height 825926
372024-01-17T21:04:37.931493Z [basic block filter index] basic block filter index thread exit
382024-01-17T21:04:37.931545Z [init] Bound to 127.0.0.1:8334
392024-01-17T21:04:37.931692Z [init] Bound to [::]:8333
402024-01-17T21:04:37.931830Z [init] Bound to 0.0.0.0:8333
412024-01-17T21:04:37.933190Z [initload] Loading 19467 mempool transactions from disk...
422024-01-17T21:04:37.933335Z [init] Loaded 2 addresses from "anchors.dat"
432024-01-17T21:04:37.934342Z [init] 2 block-relay-only anchors will be tried for connections.
442024-01-17T21:04:37.934441Z [init] init message: Starting network threads…
452024-01-17T21:04:37.934636Z [net] net thread start
462024-01-17T21:04:37.934726Z [dnsseed] dnsseed thread start
472024-01-17T21:04:37.934844Z [addcon] addcon thread start
482024-01-17T21:04:37.934962Z [opencon] opencon thread start
492024-01-17T21:04:37.935037Z [msghand] msghand thread start
502024-01-17T21:04:37.935118Z [dnsseed] Waiting 300 seconds before querying DNS seeds.
512024-01-17T21:04:37.935608Z [init] init message: Done loading
522024-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
532024-01-17T21:04:45.088087Z [msghand] Synchronizing blockheaders, height: 826175 (~100.00%)
542024-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
552024-01-17T21:04:46.518049Z [initload] Progress loading mempool transactions from disk: 10% (tried 1947, 17520 remaining)
562024-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)
572024-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)
582024-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
592024-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
602024-01-17T21:05:21.948231Z [dnsseed] P2P peers available. Skipped DNS seeding.
612024-01-17T21:05:21.948340Z [dnsseed] dnsseed thread exit
622024-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
632024-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
642024-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
652024-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
662024-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
672024-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
682024-01-17T21:06:01.649709Z [initload] Progress loading mempool transactions from disk: 20% (tried 3894, 15573 remaining)
692024-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
702024-01-17T21:06:33.410186Z [initload] Progress loading mempool transactions from disk: 30% (tried 5841, 13626 remaining)
712024-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
722024-01-17T21:07:24.909070Z [msghand] Synchronizing blockheaders, height: 826176 (~100.00%)
732024-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
742024-01-17T21:08:29.431947Z [initload] Progress loading mempool transactions from disk: 40% (tried 7787, 11680 remaining)
752024-01-17T21:11:05.226379Z [initload] Progress loading mempool transactions from disk: 50% (tried 9734, 9733 remaining)
762024-01-17T21:13:32.216591Z [initload] Progress loading mempool transactions from disk: 60% (tried 11681, 7786 remaining)
772024-01-17T21:14:03.498201Z [msghand] Synchronizing blockheaders, height: 826177 (~100.00%)
782024-01-17T21:14:45.905189Z [initload] Progress loading mempool transactions from disk: 70% (tried 13627, 5840 remaining)
792024-01-17T21:15:14.282892Z [initload] Progress loading mempool transactions from disk: 80% (tried 15574, 3893 remaining)
802024-01-17T21:15:31.923806Z [initload] Progress loading mempool transactions from disk: 90% (tried 17521, 1946 remaining)
812024-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
822024-01-17T21:15:35.950530Z [initload] initload thread exit
832024-01-17T21:18:46.843126Z [msghand] Synchronizing blockheaders, height: 826178 (~100.00%)
842024-01-17T21:19:51.712211Z [msghand] Timeout downloading block 0000000000000000000388f339429b7cdb2b9d50cf7482dea9556afdc2033d17 from peer=0 peeraddr=24.118.251.111:8333, disconnecting
852024-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
862024-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
872024-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

Post startup stalling #29281