Backport #5103 (#5123)

This PR backports hotfix from #5103

---------

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>
Co-authored-by: Alexandru Vasile <60601340+lexnv@users.noreply.github.com>
Co-authored-by: Bastian Köcher <git@kchr.de>

prdoc/1.15.0/pr_5103.prdoc

@@ -0,0 +1,18 @@
+title: Skip genesis leaf to unblock syncing
+
+doc:
+  - audience:
+    - Node Operator
+    - Node Dev
+    description: |
+      This PR skips over the genesis block reported as leaf when calculating displaced branches.
+      In those cases, when the genesis block is reported as leaf, the node would compute the path
+      from the current finalized block to the genesis block. This operation is time consuming and
+      is enough to block syncing. In the current state, the genesis block is assumed to always be
+      part of the finalized chain.
+
+crates:
+- name: sc-client-db
+  bump: none
+- name: sp-blockchain
+  bump: patch

substrate/client/db/src/lib.rs

@@ -3169,15 +3169,15 @@ pub(crate) mod tests {
 			let displaced =
 				blockchain.displaced_leaves_after_finalizing(a3_hash, a3_number).unwrap();
 			assert_eq!(blockchain.leaves().unwrap(), vec![a4_hash, genesis_hash]);
-			assert_eq!(displaced.displaced_leaves, vec![]);
+			assert_eq!(displaced.displaced_leaves, vec![(genesis_number, genesis_hash)]);
 			assert_eq!(displaced.displaced_blocks, vec![]);
 		}
 
 		{
 			let displaced =
 				blockchain.displaced_leaves_after_finalizing(a4_hash, a4_number).unwrap();
 			assert_eq!(blockchain.leaves().unwrap(), vec![a4_hash, genesis_hash]);
-			assert_eq!(displaced.displaced_leaves, vec![]);
+			assert_eq!(displaced.displaced_leaves, vec![(genesis_number, genesis_hash)]);
 			assert_eq!(displaced.displaced_blocks, vec![]);
 		}
 

substrate/primitives/blockchain/src/backend.rs

@@ -255,10 +255,11 @@ pub trait Backend<Block: BlockT>:
 	) -> std::result::Result<DisplacedLeavesAfterFinalization<Block>, Error> {
 		let leaves = self.leaves()?;
 
+		let now = std::time::Instant::now();
 		debug!(
 			target: crate::LOG_TARGET,
 			?leaves,
-			%finalized_block_hash,
+			?finalized_block_hash,
 			?finalized_block_number,
 			"Checking for displaced leaves after finalization."
 		);
@@ -277,11 +278,21 @@ pub trait Backend<Block: BlockT>:
 				debug!(
 					target: crate::LOG_TARGET,
 					hash = ?finalized_block_hash,
-					"Tried to fetch unknown block, block ancestry has gaps."
+					elapsed = ?now.elapsed(),
+					"Tried to fetch unknown block, block ancestry has gaps.",
 				);
 				return Ok(DisplacedLeavesAfterFinalization::default());
 			},
-			Err(e) => Err(e)?,
+			Err(e) => {
+				debug!(
+					target: crate::LOG_TARGET,
+					hash = ?finalized_block_hash,
+					err = ?e,
+					elapsed = ?now.elapsed(),
+					"Failed to fetch block.",
+				);
+				return Err(e);
+			},
 		};
 		finalized_chain.push_front(MinimalBlockMetadata::from(&current_finalized));
 
@@ -296,11 +307,42 @@ pub trait Backend<Block: BlockT>:
 
 		let mut displaced_blocks_candidates = Vec::new();
 
+		let genesis_hash = self.info().genesis_hash;
+
 		for leaf_hash in leaves {
 			let mut current_header_metadata =
-				MinimalBlockMetadata::from(&self.header_metadata(leaf_hash)?);
+				MinimalBlockMetadata::from(&self.header_metadata(leaf_hash).map_err(|err| {
+					debug!(
+						target: crate::LOG_TARGET,
+						?leaf_hash,
+						?err,
+						elapsed = ?now.elapsed(),
+						"Failed to fetch leaf header.",
+					);
+					err
+				})?);
 			let leaf_number = current_header_metadata.number;
 
+			// The genesis block is part of the canonical chain.
+			if leaf_hash == genesis_hash {
+				result.displaced_leaves.push((leaf_number, leaf_hash));
+				debug!(
+					target: crate::LOG_TARGET,
+					?leaf_hash,
+					elapsed = ?now.elapsed(),
+					"Added genesis leaf to displaced leaves."
+				);
+				continue
+			}
+
+			debug!(
+				target: crate::LOG_TARGET,
+				?leaf_number,
+				?leaf_hash,
+				elapsed = ?now.elapsed(),
+				"Handle displaced leaf.",
+			);
+
 			// Collect all block hashes until the height of the finalized block
 			displaced_blocks_candidates.clear();
 			while current_header_metadata.number > finalized_block_number {
@@ -312,8 +354,20 @@ pub trait Backend<Block: BlockT>:
 						current_header_metadata = *metadata_header;
 					},
 					None => {
-						current_header_metadata =
-							MinimalBlockMetadata::from(&self.header_metadata(parent_hash)?);
+						current_header_metadata = MinimalBlockMetadata::from(
+							&self.header_metadata(parent_hash).map_err(|err| {
+								debug!(
+									target: crate::LOG_TARGET,
+									?err,
+									?parent_hash,
+									?leaf_hash,
+									elapsed = ?now.elapsed(),
+									"Failed to fetch parent header during leaf tracking.",
+								);
+
+								err
+							})?,
+						);
 						// Cache locally in case more branches above finalized block reference
 						// the same block hash
 						local_cache.insert(parent_hash, current_header_metadata);
@@ -324,6 +378,13 @@ pub trait Backend<Block: BlockT>:
 			// If points back to the finalized header then nothing left to do, this leaf will be
 			// checked again later
 			if current_header_metadata.hash == finalized_block_hash {
+				debug!(
+					target: crate::LOG_TARGET,
+					?leaf_hash,
+					elapsed = ?now.elapsed(),
+					"Leaf points to the finalized header, skipping for now.",
+				);
+
 				continue;
 			}
 
@@ -332,6 +393,15 @@ pub trait Backend<Block: BlockT>:
 			// check for this gap later.
 			displaced_blocks_candidates.push(current_header_metadata.hash);
 
+			debug!(
+				target: crate::LOG_TARGET,
+				current_hash = ?current_header_metadata.hash,
+				current_num = ?current_header_metadata.number,
+				?finalized_block_number,
+				elapsed = ?now.elapsed(),
+				"Looking for path from finalized block number to current leaf number"
+			);
+
 			// Collect the rest of the displaced blocks of leaf branch
 			for distance_from_finalized in 1_u32.. {
 				// Find block at `distance_from_finalized` from finalized block
@@ -348,11 +418,22 @@ pub trait Backend<Block: BlockT>:
 										distance_from_finalized,
 										hash = ?to_fetch.parent,
 										number = ?to_fetch.number,
+										elapsed = ?now.elapsed(),
 										"Tried to fetch unknown block, block ancestry has gaps."
 									);
 									break;
 								},
-								Err(e) => Err(e)?,
+								Err(err) => {
+									debug!(
+										target: crate::LOG_TARGET,
+										hash = ?to_fetch.parent,
+										number = ?to_fetch.number,
+										?err,
+										elapsed = ?now.elapsed(),
+										"Failed to fetch header for parent hash.",
+									);
+									return Err(err);
+								},
 							};
 							let metadata = MinimalBlockMetadata::from(&metadata);
 							let result = (metadata.number, metadata.hash);
@@ -361,6 +442,19 @@ pub trait Backend<Block: BlockT>:
 						},
 					};
 
+				if current_header_metadata.hash == finalized_chain_block_hash {
+					// Found the block on the finalized chain, nothing left to do
+					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;
+				}
+
 				if current_header_metadata.number <= finalized_chain_block_number {
 					// Skip more blocks until we get all blocks on finalized chain until the height
 					// of the parent block
@@ -372,20 +466,52 @@ pub trait Backend<Block: BlockT>:
 					// Reached finalized chain, nothing left to do
 					result.displaced_blocks.extend(displaced_blocks_candidates.drain(..));
 					result.displaced_leaves.push((leaf_number, leaf_hash));
+
+					debug!(
+						target: crate::LOG_TARGET,
+						?leaf_hash,
+						elapsed = ?now.elapsed(),
+						"Found displaced leaf."
+					);
 					break;
 				}
 
 				// Store displaced block and look deeper for block on finalized chain
+				debug!(
+					target: crate::LOG_TARGET,
+					?parent_hash,
+					elapsed = ?now.elapsed(),
+					"Found displaced block. Looking further.",
+				);
 				displaced_blocks_candidates.push(parent_hash);
-				current_header_metadata =
-					MinimalBlockMetadata::from(&self.header_metadata(parent_hash)?);
+				current_header_metadata = MinimalBlockMetadata::from(
+					&self.header_metadata(parent_hash).map_err(|err| {
+						debug!(
+							target: crate::LOG_TARGET,
+							?err,
+							?parent_hash,
+							elapsed = ?now.elapsed(),
+							"Failed to fetch header for parent during displaced block collection",
+						);
+						err
+					})?,
+				);
 			}
 		}
 
 		// There could be duplicates shared by multiple branches, clean them up
 		result.displaced_blocks.sort_unstable();
 		result.displaced_blocks.dedup();
 
+		debug!(
+			target: crate::LOG_TARGET,
+			%finalized_block_hash,
+			?finalized_block_number,
+			?result,
+			elapsed = ?now.elapsed(),
+			"Finished checking for displaced leaves after finalization.",
+		);
+
 		return Ok(result);
 	}
 }

substrate/zombienet/0001-basic-warp-sync/test-warp-sync.toml

@@ -27,4 +27,4 @@ chain_spec_path = "chain-spec.json"
   [[relaychain.nodes]]
   name = "dave"
   validator = false
-  args = ["--sync warp"]
+  args = ["--sync warp -ldb::blockchain"]

substrate/zombienet/0001-basic-warp-sync/test-warp-sync.zndsl

@@ -22,6 +22,7 @@ dave: reports block height is at least 1 within 60 seconds
 dave: reports block height is at least {{DB_BLOCK_HEIGHT}} within 60 seconds
 
 dave: log line matches "Warp sync is complete" within 60 seconds
+dave: log line matches "Checking for displaced leaves after finalization\. leaves\=\[0xc5e7b4cfd23932bb930e859865430a35f6741b4732d677822d492ca64cc8d059\]" within 10 seconds
 # State sync is logically part of warp sync
 dave: log line matches "State sync is complete" within 60 seconds
 dave: log line matches "Block history download is complete" within 10 seconds