Post startup stalling #29281

issue fanquake openend this issue on January 19, 2024
  1. 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)
    
  2. fanquake added the label P2P on Jan 19, 2024
  3. 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.

  4. 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.
  5. 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.
  6. mzumsande commented at 10:28 pm on March 15, 2024: contributor
    see #29664

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: 2024-12-11 06:12 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me