Sync does not continue after reindex until a block is inved #8239

At startup, we ask for headers leading up to the tip from every new peer we connect to or accept a connection from if we believe we're synced. This immediately bootstraps the parallel block fetches that keeps us in sync.

However, when we reindex, we usually have all connection slots already filled by the time the reindex finishes, and we don't go back to ask for headers from existing connections. This usually leads to a wait until the next block is inved.

This problem is likely worsed by #7917, as it may now also trigger in cases where the chainstate is behind the blockindex.

In my testing of #24858, I have not experienced what I think this issue describes. Is this issue stale and closable, or have I misunderstood? For example, in my debug.log, I see the "initial getheaders" message in the same second as the "loadblk thread exit" and there is no intervening block inv.

2022-04-18T10:26:25Z loadblk thread exit
2022-04-18T10:26:25Z UpdatedBlockTip: new block hash=000000000000453154dc06cf8a4d0caba8247de3999e6501a441dfba0129df33 fork block hash=0000000000000208f44ba18047fddd3aeaed7faf28bd5493609596f9e2a8e1cd (in I
BD=true)
2022-04-18T10:26:25Z BlockConnected: block hash=0000000000001cf475ca2791a37145307500b752d7ea8d57d513a4d77cf7c7eb block height=119962
2022-04-18T10:26:25Z UpdatedBlockTip: new block hash=0000000000001cf475ca2791a37145307500b752d7ea8d57d513a4d77cf7c7eb fork block hash=000000000000453154dc06cf8a4d0caba8247de3999e6501a441dfba0129df33 (in I
BD=true)
2022-04-18T10:26:25Z BlockConnected: block hash=00000000000001a831ab6fbd4fa8c1bb98f1f07f0ceb1c5c1a8a2b4c8b567e8b block height=119963
2022-04-18T10:26:25Z UpdatedBlockTip: new block hash=00000000000001a831ab6fbd4fa8c1bb98f1f07f0ceb1c5c1a8a2b4c8b567e8b fork block hash=0000000000001cf475ca2791a37145307500b752d7ea8d57d513a4d77cf7c7eb (in I
BD=true)
2022-04-18T10:26:25Z BlockConnected: block hash=00000000000064ac7c1b57c1d3b4fd3a3aeb2f26c96c2dde853eef230a271048 block height=119964
2022-04-18T10:26:25Z UpdatedBlockTip: new block hash=00000000000064ac7c1b57c1d3b4fd3a3aeb2f26c96c2dde853eef230a271048 fork block hash=00000000000001a831ab6fbd4fa8c1bb98f1f07f0ceb1c5c1a8a2b4c8b567e8b (in I
BD=true)
2022-04-18T10:26:25Z initial getheaders (119963) to peer=14 (startheight:732408)
2022-04-18T10:26:25Z sending getheaders (933 bytes) peer=14
2022-04-18T10:26:25Z sending ping (8 bytes) peer=0
2022-04-18T10:26:25Z received: ping (8 bytes) peer=0
2022-04-18T10:26:25Z sending pong (8 bytes) peer=0
2022-04-18T10:26:25Z received: pong (8 bytes) peer=0
2022-04-18T10:26:27Z received: headers (162003 bytes) peer=14
2022-04-18T10:26:27Z Synchronizing blockheaders, height: 121963 (~17.47%)
2022-04-18T10:26:27Z more getheaders (121963) to end to peer=14 (startheight:732408)
2022-04-18T10:26:27Z sending getheaders (933 bytes) peer=14
2022-04-18T10:26:28Z received: headers (162003 bytes) peer=14
2022-04-18T10:26:28Z Synchronizing blockheaders, height: 123963 (~17.74%)
2022-04-18T10:26:28Z more getheaders (123963) to end to peer=14 (startheight:732408)

height=119964

I haven't looked at this at all, but the sync logic might differ for blocks less heavy than the minimum chain work?

It doesn't appear to be as of what's in master right now: https://github.com/bitcoin/bitcoin/blob/master/src/net_processing.cpp#L4672-L4701

It is gated by fImporting which is released in ThreadImport shortly before the log message loadblk thread exit is made. I think this issue is probably stale unless there is something subtle that I am not picking up on.

I also seem unable to reproduce this behaviour on master at 7f2019755d, but I didn't check on mainnet with a long chain (and high chain work as suggested by Marco), instead I stopped a regtest node (a) in GDB while it was reindexing and generated new blocks on a second already-connected node (b), before continuing with the reindex.

The headers were received on node (a) before the reindex had completed, which then sent getheaders and synced to the new tip, without recieving any further block invs:

<details> <summary>Details</summary>

2023-06-05T12:24:02Z loadblk thread start
[Switching to Thread 0x7fffacff96c0 (LWP 505309)]

Thread 23 "b-loadblk" hit Breakpoint 1, node::ThreadImport (chainman=..., vImportFiles=std::vector of length 0, capacity 0, mempool_path=...) at node/blockstorage.cpp:880
# reindex blocks up to 240, current tip
...
2023-06-05T12:24:10Z [validation:debug] Saw new header hash=6643009b0170e505bdab690f221ab16dc9544733fe7a049983b9ac8c4d59498b height=237
2023-06-05T12:24:10Z [validation:debug] Saw new header hash=331dd8d6194c44104bcd848251f27a60f97822f461cf15ef0cc1ef87b34a209c height=238
2023-06-05T12:24:10Z [validation:debug] Saw new header hash=2ed8cf4999897a0c99bb4f38b8d365c0901fc9799c3ac4a4eb8ee3d6ce14fc5d height=239
2023-06-05T12:24:10Z [validation:debug] Saw new header hash=55d43ad6e0525a44eac9cfc4492565428c5bca38b626404ac17c1a9ee21511d9 height=240

# node receives new block inv while reindex in progress
...
2023-06-05T12:26:21Z [net] sending ping (8 bytes) peer=0
2023-06-05T12:26:21Z [lock] Enter: lock contention m_events_mutex, random.cpp:355 started
2023-06-05T12:26:21Z [lock] Enter: lock contention m_events_mutex, random.cpp:355 completed (1μs)
2023-06-05T12:26:21Z [lock] Enter: lock contention m_nodes_mutex, net.cpp:1111 started
2023-06-05T12:26:21Z [lock] Enter: lock contention m_nodes_mutex, net.cpp:1111 completed (1μs)
2023-06-05T12:26:21Z [net] received: ping (8 bytes) peer=0
2023-06-05T12:26:21Z [net] sending pong (8 bytes) peer=0
2023-06-05T12:26:21Z [lock] Enter: lock contention pnode->cs_vSend, net.cpp:1234 started
2023-06-05T12:26:21Z [lock] Enter: lock contention pnode->cs_vSend, net.cpp:1234 completed (6μs)
2023-06-05T12:26:21Z [net] received: inv (37 bytes) peer=0
2023-06-05T12:26:21Z [net] got inv: block 7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7  new peer=0

# reindexing finished
...
2023-06-05T12:26:37Z [leveldb] WriteBatch memory usage: db=index, before=0.0MiB, after=0.0MiB
2023-06-05T12:26:37Z Reindexing finished

# After reindexing we send `getheaders` and recieve back the new header hash
...
2023-06-05T12:26:37Z loadblk thread exit
...
2023-06-05T12:26:37Z [validation] BlockConnected: block hash=55d43ad6e0525a44eac9cfc4492565428c5bca38b626404ac17c1a9ee21511d9 block height=240
2023-06-05T12:26:37Z [validation] UpdatedBlockTip: new block hash=55d43ad6e0525a44eac9cfc4492565428c5bca38b626404ac17c1a9ee21511d9 fork block hash=2ed8cf4999897a0c99bb4f38b8d365c0901fc9799c3ac4a4eb8ee3d6ce14fc5d (in IBD=true)
2023-06-05T12:26:37Z [net] sending getheaders (645 bytes) peer=0
2023-06-05T12:26:37Z [net] initial getheaders (239) to peer=0 (startheight:240)
2023-06-05T12:26:37Z Leaving InitialBlockDownload (latching to false)
2023-06-05T12:26:37Z [net] sending feefilter (8 bytes) peer=0
2023-06-05T12:26:37Z [net] received: headers (8263 bytes) peer=0
2023-06-05T12:26:37Z Saw new header hash=7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 height=241


# request the header & block
...
2023-06-05T12:26:37Z [net] sending sendheaders (0 bytes) peer=0
2023-06-05T12:26:37Z [net] Requesting block 7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 (241) peer=0

# and connect it
...
2023-06-05T12:26:37Z [net] received block 7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 peer=0
2023-06-05T12:26:37Z [validation] NewPoWValidBlock: block hash=7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7
2023-06-05T12:26:37Z [bench]   - Using cached block
2023-06-05T12:26:37Z [bench]   - Load block from disk: 0.02ms
2023-06-05T12:26:37Z [bench]     - Sanity checks: 0.00ms [0.00s (0.01ms/blk)]
2023-06-05T12:26:37Z [bench]     - Fork checks: 0.04ms [0.01s (0.03ms/blk)]
2023-06-05T12:26:37Z [bench]       - Connect 1 transactions: 0.03ms (0.030ms/tx, 0.000ms/txin) [0.01s (0.02ms/blk)]
2023-06-05T12:26:37Z [bench]     - Verify 0 txins: 0.06ms (0.000ms/txin) [0.01s (0.04ms/blk)]
2023-06-05T12:26:37Z [bench]     - Write undo data: 0.04ms [0.01s (0.03ms/blk)]
2023-06-05T12:26:37Z [bench]     - Index writing: 0.01ms [0.00s (0.01ms/blk)]
2023-06-05T12:26:37Z [validation] BlockChecked: block hash=7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 state=Valid
2023-06-05T12:26:37Z [bench]   - Connect total: 0.22ms [0.05s (0.19ms/blk)]
2023-06-05T12:26:37Z [bench]   - Flush: 0.03ms [0.01s (0.03ms/blk)]
2023-06-05T12:26:37Z [bench]   - Writing chainstate: 0.02ms [0.00s (0.02ms/blk)]
2023-06-05T12:26:37Z [estimatefee] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
2023-06-05T12:26:37Z UpdateTip: new best=7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 height=241 version=0x30000000 log2_work=8.918863 tx=242 date='2023-06-05T12:26:13Z' progress=1.000000 cache=0.3MiB(241txo)
2023-06-05T12:26:37Z [bench]   - Connect postprocess: 0.32ms [0.01s (0.04ms/blk)]
2023-06-05T12:26:37Z [bench] - Connect block: 0.61ms [0.08s (0.31ms/blk)]
2023-06-05T12:26:37Z [mempool] Checking mempool with 0 transactions and 0 inputs
2023-06-05T12:26:37Z [validation] Enqueuing BlockConnected: block hash=7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 block height=241
2023-06-05T12:26:37Z [validation] Enqueuing UpdatedBlockTip: new block hash=7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 fork block hash=55d43ad6e0525a44eac9cfc4492565428c5bca38b626404ac17c1a9ee21511d9 (in IBD=false)
2023-06-05T12:26:37Z [validation] BlockConnected: block hash=7a57bd5ce9153d85a71240c74b01869a696e921bbafe6bf0a1ef4f06f16694f7 block height=241

</details>

Perhaps this testing method is circumventing the behaviour described in OP, but otherwise it appears that it could only be an issue in the case that no new block is found during the entire -reindex process, which seems unlikely?

I agree and think that this can be closed, this line sends out the "initial getheaders" to one or more peers only after the reindex is finished (m_blockman.LoadingBlocks() switches to false, and fSyncStarted cannot be true before that). This should be independent of whether any new blocks were found during the reindex or not.