hotfix: blockchain/backend: Skip genesis leaf to unblock syncing

[lexnv]

This PR effectively skips over cases where the blockchain reports the genesis block as leaf.

The issue manifests as the blockchain getting stuck and not importing blocks after a while.
Although the root-cause of why the blockchain reports the genesis as leaf is not scoped, this hot-fix is unblocking the new release.

While at it, added some extra debug logs to identify issues more easily in the future.

Issue

2024-07-22 10:06:08.708 DEBUG tokio-runtime-worker db::blockchain: Checking for displaced leaves after finalization. leaves=[0xd62aea69664b74c55b7e79ab5855b117d213156a5e9ab05ad0737772aaf42c14, 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe] finalized_block_hash=0x8f8e…7f34 finalized_block_number=24148459
2024-07-22 10:06:08.708 DEBUG tokio-runtime-worker db::blockchain: Handle displaced leaf 0xd62aea69664b74c55b7e79ab5855b117d213156a5e9ab05ad0737772aaf42c14 (elapsed 25.74µs) leaf_number=24148577
2024-07-22 10:06:08.709 DEBUG tokio-runtime-worker db::blockchain: Leaf points to the finalized header 0xd62aea69664b74c55b7e79ab5855b117d213156a5e9ab05ad0737772aaf42c14, skipping for now (elapsed 70.72µs)


// This is Kusama genesis
2024-07-22 10:06:08.709 DEBUG tokio-runtime-worker db::blockchain: Handle displaced leaf 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe (elapsed 127.271µs) leaf_number=0
2024-07-22 10:06:08.709 DEBUG tokio-runtime-worker db::blockchain: Skip more blocks until we get all blocks on finalized chain until the height of the parent block current_hash=0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe current_num=0 finalized_num=24148458

Before

2024-07-20 00:45:00.234  INFO tokio-runtime-worker substrate: ⚙️  Preparing  0.0 bps, target=#24116589 (50 peers), best: #24116498 (0xb846…8720), finalized #24116493 (0x50b6…2445), ⬇ 2.3MiB/s ⬆ 2.6kiB/s    
   
...

2024-07-20 14:05:18.572  INFO tokio-runtime-worker substrate: ⚙️  Syncing  0.0 bps, target=#24124495 (51 peers), best: #24119976 (0x6970…aeb3), finalized #24119808 (0xd900…abe4), ⬇ 2.2MiB/s ⬆ 3.1kiB/s    
2024-07-20 14:05:23.573  INFO tokio-runtime-worker substrate: ⚙️  Syncing  0.0 bps, target=#24124495 (51 peers), best: #24119976 (0x6970…aeb3), finalized #24119808 (0xd900…abe4), ⬇ 2.2MiB/s ⬆ 5.8kiB/s    

After

2024-07-22 10:41:10.897 DEBUG tokio-runtime-worker db::blockchain: Handle displaced leaf 0x4e8cf3ff18e7d13ff7fec28f9fc8ce6eff5492ed8dc046e961b76dec5c0cfddf (elapsed 39.26µs) leaf_number=24150969
2024-07-22 10:41:10.897 DEBUG tokio-runtime-worker db::blockchain: Leaf points to the finalized header 0x4e8cf3ff18e7d13ff7fec28f9fc8ce6eff5492ed8dc046e961b76dec5c0cfddf, skipping for now (elapsed 49.69µs)
2024-07-22 10:41:10.897 DEBUG tokio-runtime-worker db::blockchain: Skip genesis block 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe reporterd as leaf (elapsed 54.57µs)
2024-07-22 10:41:10.897 DEBUG tokio-runtime-worker db::blockchain: Finished with result DisplacedLeavesAfterFinalization { displaced_leaves: [], displaced_blocks: [] } (elapsed 58.78µs) finalized_block_hash=0x02b3…5338 finalized_block_number=24150967
2024-07-22 10:41:12.357  INFO tokio-runtime-worker substrate: 🏆 Imported #24150970 (0x4e8c…fddf → 0x3637…56bb)
2024-07-22 10:41:12.862  INFO tokio-runtime-worker substrate: 💤 Idle (50 peers), best: #24150970 (0x3637…56bb), finalized #24150967 (0x02b3…5338), ⬇ 2.0MiB/s ⬆ 804.7kiB/s
2024-07-22 10:41:14.772 DEBUG tokio-runtime-worker db::blockchain: Checking for displaced leaves after finalization. leaves=[0x363763b16c23fc20a84f38f67014fa7ae6ba9c708fc074890016699e5ca756bb, 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe] finalized_block_hash=0xa1534a105b90e7036a18ac1c646cd2bd6c41c66cc055817f4f51209ab9070e5c finalized_block_number=24150968
2024-07-22 10:41:14.772 DEBUG tokio-runtime-worker db::blockchain: Handle displaced leaf 0x363763b16c23fc20a84f38f67014fa7ae6ba9c708fc074890016699e5ca756bb (elapsed 62.48µs) leaf_number=24150970
2024-07-22 10:41:14.772 DEBUG tokio-runtime-worker db::blockchain: Leaf points to the finalized header 0x363763b16c23fc20a84f38f67014fa7ae6ba9c708fc074890016699e5ca756bb, skipping for now (elapsed 71.76µs)
2024-07-22 10:41:14.772 DEBUG tokio-runtime-worker db::blockchain: Skip genesis block 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe reporterd as leaf (elapsed 75.96µs)
2024-07-22 10:41:14.772 DEBUG tokio-runtime-worker db::blockchain: Finished with result DisplacedLeavesAfterFinalization { displaced_leaves: [], displaced_blocks: [] } (elapsed 80.27µs) finalized_block_hash=0xa153…0e5c finalized_block_number=24150968
2024-07-22 10:41:14.795 DEBUG tokio-runtime-worker db::blockchain: Checking for displaced leaves after finalization. leaves=[0x363763b16c23fc20a84f38f67014fa7ae6ba9c708fc074890016699e5ca756bb, 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe] finalized_block_hash=0xa1534a105b90e7036a18ac1c646cd2bd6c41c66cc055817f4f51209ab9070e5c finalized_block_number=24150968
2024-07-22 10:41:14.795 DEBUG tokio-runtime-worker db::blockchain: Handle displaced leaf 0x363763b16c23fc20a84f38f67014fa7ae6ba9c708fc074890016699e5ca756bb (elapsed 39.67µs) leaf_number=24150970
2024-07-22 10:41:14.795 DEBUG tokio-runtime-worker db::blockchain: Leaf points to the finalized header 0x363763b16c23fc20a84f38f67014fa7ae6ba9c708fc074890016699e5ca756bb, skipping for now (elapsed 50.3µs)
2024-07-22 10:41:14.795 DEBUG tokio-runtime-worker db::blockchain: Skip genesis block 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe reporterd as leaf (elapsed 54.52µs)
2024-07-22 10:41:14.795 DEBUG tokio-runtime-worker db::blockchain: Finished with result DisplacedLeavesAfterFinalization { displaced_leaves: [], displaced_blocks: [] } (elapsed 58.66µs) finalized_block_hash=0xa153…0e5c finalized_block_number=24150968
2024-07-22 10:41:17.863  INFO tokio-runtime-worker substrate: 💤 Idle (50 peers), best: #24150970 (0x3637…56bb), finalized #24150968 (0xa153…0e5c), ⬇ 1.2MiB/s ⬆ 815.0kiB/s
2024-07-22 10:41:18.399  INFO tokio-runtime-worker substrate: 🏆 Imported #24150971 (0x3637…56bb → 0x4ee3…5f7c)

Closes: #5088

[skunert]

In my opinion the correct abort condition here would be to to insert a check here:
https://github.com/paritytech/polkadot-sdk/pull/5103/files#diff-37542b5b93e687ac878ece2ca83625c87aa26cf014cff6dff76459bbf3ed751eR424

The check should be:

if current_header_metadata.hash == finalized_chain_block_hash {
	result.displaced_leaves.push((leaf_number, leaf_hash));
	debug!(
		target: crate::LOG_TARGET,
		?leaf_hash,
		elapsed = ?now.elapsed(),
		"Leaf is ancestor of finalized block" );
	break;
}

Basically these situations should be covered by this:
(l) = marked as leaf
(f) = to-be-finalized

G(l) -> A -> B -> C(f) -> D

Genesis block G should be marked as displaced leaf. An ancestor of the finalized block is not a leaf.

G -> A -> B(l) -> C(f) -> D

Here block B should be marked as displaced leafs. However in both cases B and G should not be marked as displaced blocks.

G -> A -> B(l) -> ... GAP ... C(f) -> D

If there is a gap in between we leave B alone for now.

[skunert]

Nit: IMO since we are using tracing lib now we should not use the inline formatting but the structured logging only. This plus some consistend naming gives us nicely formatted logs.

[bkchr]

https://github.com/paritytech/polkadot-sdk/pull/5103/files#diff-37542b5b93e687ac878ece2ca83625c87aa26cf014cff6dff76459bbf3ed751eR424

You are basically repeating the check some lines below for parent_hash. This will also fail until we have the gap synced.

I think we should simplify this even more and put here the following:

if leaf_number < finalized_block_number {
    result.displaced_leaves.push((leaf_number, leaf_hash));

    // go from leaf to finalized chain
    // by getting the hash at block `n` (starting with `leaf_number - 1`)
    // Compare if the hash at `n` is the same hash of the block of the fork
    // If not, go up and compare the same and push the block to `displaced_blocks`.

   continue
}

Generally this should be faster, as we don't need to go down from the tip of the chain back to genesis block in the case of warp syncing. Also for most of the other cases it should probably be faster.

[skunert]

You are basically repeating the check some lines below for parent_hash. This will also fail until we have the gap synced.

Yes that is true, however we don't want to iterate to the parent, as its not available for the genesis block.

This will also fail until we have the gap synced.

Wdym by this? We will go the "unknown block" route while the gap exists. This is intended however, see the discussion here
#4997. Once the gap is closed, we will prune the leafs that are now connected to the finalized block.

Your proposed solution works in the short term, but currently we are accepting leaves that could be below the gap, and we should not break that.

[bkchr]

Let's use @skunert proposal and call it a day. We need to really refactor this beast of pruning logic to make it easier to reason about.

[ggwpez]

Can you please add a prdoc? R0-silent currently bypasses that requirement, but i think it makes sense for hotfixes that should appear in the CHANGELOG.

[lexnv]

After some testing, we have decided to add an extra check for the genesis hash.
The node would compute the path from the finalized block to the genesis. And this is a time consuming operation, enough to block (extremely slow down) syncing

In the current state, syncing is unblocked and this case is entirely skipped:

2024-07-23 12:21:10.709  INFO tokio-runtime-worker substrate: ⚙️  Syncing 12.0 bps, target=#24166221 (50 peers), best: #24162231 (0xb7ef…5984), finalized #24161792 (0x0441…81f7), ⬇ 1.9MiB/s ⬆ 2.4MiB/s
2024-07-23 12:21:15.709  INFO tokio-runtime-worker substrate: ⚙️  Syncing 12.2 bps, target=#24166222 (50 peers), best: #24162292 (0x1e84…23dd), finalized #24161792 (0x0441…81f7), ⬇ 1.8MiB/s ⬆ 909.6kiB/s
2024-07-23 12:21:16.648 DEBUG tokio-runtime-worker db::blockchain: Checking for displaced leaves after finalization. leaves=[0xf5c3d20ace32f3cdc34e2ac5d3bc28b99b1e043e3a386ba932c3cb18c6a6d1bb] finalized_block_hash=0xf5c3d20ace32f3cdc34e2ac5d3bc28b99b1e043e3a386ba932c3cb18c6a6d1bb finalized_block_number=24162304
2024-07-23 12:21:17.581 DEBUG tokio-runtime-worker db::blockchain: Checking for displaced leaves after finalization. leaves=[0xf5c3d20ace32f3cdc34e2ac5d3bc28b99b1e043e3a386ba932c3cb18c6a6d1bb] finalized_block_hash=0xf5c3d20ace32f3cdc34e2ac5d3bc28b99b1e043e3a386ba932c3cb18c6a6d1bb finalized_block_number=24162304
2024-07-23 12:21:20.709  INFO tokio-runtime-worker substrate: ⚙️  Syncing  3.2 bps, target=#24166223 (50 peers), best: #24162308 (0x923c…e5ea), finalized #24162304 (0xf5c3…d1bb), ⬇ 2.0MiB/s ⬆ 796.2kiB/s
2024-07-23 12:21:25.710  INFO tokio-runtime-worker substrate: ⚙️  Syncing 10.6 bps, target=#24166224 (50 peers), best: #24162361 (0x79be…7273), finalized #24162304 (0xf5c3…d1bb), ⬇ 3.0MiB/s ⬆ 645.9kiB/s

[bkchr]

Suggested change

	// The genesis block is never displaced, as it is part of the canonical chain.
	let genesis_hash = self.info().genesis_hash;
	let leaves = self.leaves()?.into_iter().filter(|h| *h != genesis_hash).collect::<Vec<_>>();
	let leaves = self.leaves()?;

We want that the genesis leaf is removed.

[bkchr]

The node would compute the path from the finalized block to the genesis. And this is a time consuming operation, enough to block (extremely slow down) syncing

This is what I said above

Generally this should be faster, as we don't need to go down from the tip of the chain back to genesis block in the case of warp syncing. Also for most of the other cases it should probably be faster.

I'm not sure that just skipping the genesis leaf is a smart move. It works here, but everything else that uses the leaves will continue to consume the genesis leaf. So, we maybe just move the problem to somewhere else.

TLDR: We need to prune it.

Maybe to move this forward, bring back your initial hack and with checking the genesis_hash and then we really need to come up with something better.

[skunert]

TLDR: We need to prune it.

Maybe to move this forward, bring back your initial hack and with checking the genesis_hash and then we really need to come up with something better.

Yes, instead of just skipping, should be added to displaced leafs. AFAIK this is what were were doing before the touching of this code started.

[paritytech-cicd-pr]

The CI pipeline was cancelled due to failure one of the required jobs.
Job name: test-linux-stable 3/3
Logs: https://gitlab.parity.io/parity/mirrors/polkadot-sdk/-/jobs/6785220