Better logging when backfilling ancient blocks fail

ethcore/blockchain/src/best_block.rs

@@ -24,7 +24,8 @@ use common_types::header::Header;
 /// For GHOST fork-choice rule it would typically describe the block with highest
 /// combined difficulty (usually the block with the highest block number).
 ///
-/// Sometimes refered as 'latest block'.
+/// Sometimes referred as 'latest block'.
+#[derive(Debug)]
 pub struct BestBlock {
 	/// Best block decoded header.
 	pub header: Header,
@@ -35,7 +36,7 @@ pub struct BestBlock {
 }
 
 /// Best ancient block info. If the blockchain has a gap this keeps track of where it starts.
-#[derive(Default)]
+#[derive(Debug, Default)]
 pub struct BestAncientBlock {
 	/// Best block hash.
 	pub hash: H256,

ethcore/blockchain/src/blockchain.rs

@@ -652,10 +652,7 @@ impl BlockChain {
 			// and write them
 			if let (Some(hash), Some(number)) = (best_ancient, best_ancient_number) {
 				let mut best_ancient_block = bc.best_ancient_block.write();
-				*best_ancient_block = Some(BestAncientBlock {
-					hash: hash,
-					number: number,
-				});
+				*best_ancient_block = Some(BestAncientBlock { hash, number });
 			}
 		}
 

ethcore/db/src/keys.rs

@@ -205,7 +205,7 @@ pub struct TransactionAddress {
 }
 
 /// Contains all block receipts.
-#[derive(Clone, RlpEncodableWrapper, RlpDecodableWrapper, MallocSizeOf)]
+#[derive(Debug, Clone, RlpEncodableWrapper, RlpDecodableWrapper, MallocSizeOf)]
 pub struct BlockReceipts {
 	/// Block receipts
 	pub receipts: Vec<Receipt>,
@@ -214,9 +214,7 @@ pub struct BlockReceipts {
 impl BlockReceipts {
 	/// Create new block receipts wrapper.
 	pub fn new(receipts: Vec<Receipt>) -> Self {
-		BlockReceipts {
-			receipts: receipts
-		}
+		BlockReceipts { receipts }
 	}
 }
 

ethcore/src/snapshot/consensus/authority.rs

@@ -348,7 +348,7 @@ impl Rebuilder for ChunkRebuilder {
 		Ok(())
 	}
 
-	fn finalize(&mut self, _engine: &dyn EthEngine) -> Result<(), ::error::Error> {
+	fn finalize(&mut self) -> Result<(), ::error::Error> {
 		if !self.had_genesis {
 			return Err(Error::WrongChunkFormat("No genesis transition included.".into()).into());
 		}
@@ -358,6 +358,7 @@ impl Rebuilder for ChunkRebuilder {
 			None => return Err(Error::WrongChunkFormat("Warp target block not included.".into()).into()),
 		};
 
+		trace!(target: "snapshot", "rebuilder, finalize: verifying {} unverified first blocks", self.unverified_firsts.len());
 		// verify the first entries of chunks we couldn't before.
 		// we store all last verifiers, but not all firsts.
 		// match each unverified first epoch with a last epoch verifier.

ethcore/src/snapshot/consensus/mod.rs

@@ -92,5 +92,5 @@ pub trait Rebuilder: Send {
 	///
 	/// This should apply the necessary "glue" between chunks,
 	/// and verify against the restored state.
-	fn finalize(&mut self, engine: &dyn EthEngine) -> Result<(), ::error::Error>;
+	fn finalize(&mut self) -> Result<(), ::error::Error>;
 }

ethcore/src/snapshot/consensus/work.rs

@@ -208,15 +208,15 @@ impl PowRebuilder {
 	/// Create a new PowRebuilder.
 	fn new(chain: BlockChain, db: Arc<dyn KeyValueDB>, manifest: &ManifestData, snapshot_blocks: u64) -> Result<Self, ::error::Error> {
 		Ok(PowRebuilder {
-			chain: chain,
-			db: db,
+			chain,
+			db,
 			rng: OsRng::new().map_err(|e| format!("{}", e))?,
 			disconnected: Vec::new(),
 			best_number: manifest.block_number,
 			best_hash: manifest.block_hash,
 			best_root: manifest.state_root,
 			fed_blocks: 0,
-			snapshot_blocks: snapshot_blocks,
+			snapshot_blocks,
 		})
 	}
 }
@@ -298,9 +298,9 @@ impl Rebuilder for PowRebuilder {
 	}
 
 	/// Glue together any disconnected chunks and check that the chain is complete.
-	fn finalize(&mut self, _: &dyn EthEngine) -> Result<(), ::error::Error> {
+	fn finalize(&mut self) -> Result<(), ::error::Error> {
 		let mut batch = self.db.transaction();
-
+		trace!(target: "snapshot", "rebuilder, finalize: inserting {} disconnected chunks", self.disconnected.len());
 		for (first_num, first_hash) in self.disconnected.drain(..) {
 			let parent_num = first_num - 1;
 

ethcore/src/snapshot/error.rs

@@ -68,8 +68,8 @@ pub enum Error {
 	BadEpochProof(u64),
 	/// Wrong chunk format.
 	WrongChunkFormat(String),
-	/// Unlinked ancient block chain
-	UnlinkedAncientBlockChain,
+	/// Unlinked ancient block chain; includes the parent hash where linkage failed
+	UnlinkedAncientBlockChain(H256),
 }
 
 impl error::Error for Error {
@@ -108,7 +108,7 @@ impl fmt::Display for Error {
 			Error::SnapshotAborted => write!(f, "Snapshot was aborted."),
 			Error::BadEpochProof(i) => write!(f, "Bad epoch proof for transition to epoch {}", i),
 			Error::WrongChunkFormat(ref msg) => write!(f, "Wrong chunk format: {}", msg),
-			Error::UnlinkedAncientBlockChain => write!(f, "Unlinked ancient blocks chain"),
+			Error::UnlinkedAncientBlockChain(parent_hash) => write!(f, "Unlinked ancient blocks chain at parent_hash={}", parent_hash),
 		}
 	}
 }

ethcore/src/snapshot/service.rs

@@ -110,17 +110,17 @@ impl Restoration {
 
 		let secondary = components.rebuilder(chain, raw_db.clone(), &manifest)?;
 
-		let root = manifest.state_root.clone();
+		let final_state_root = manifest.state_root.clone();
 
 		Ok(Restoration {
-			manifest: manifest,
+			manifest,
 			state_chunks_left: state_chunks,
 			block_chunks_left: block_chunks,
 			state: StateRebuilder::new(raw_db.key_value().clone(), params.pruning),
-			secondary: secondary,
+			secondary,
 			writer: params.writer,
 			snappy_buffer: Vec::new(),
-			final_state_root: root,
+			final_state_root,
 			guard: params.guard,
 			db: raw_db,
 		})
@@ -170,7 +170,7 @@ impl Restoration {
 	}
 
 	// finish up restoration.
-	fn finalize(mut self, engine: &dyn EthEngine) -> Result<(), Error> {
+	fn finalize(mut self) -> Result<(), Error> {
 		use trie::TrieError;
 
 		if !self.is_done() { return Ok(()) }
@@ -186,13 +186,14 @@ impl Restoration {
 		self.state.finalize(self.manifest.block_number, self.manifest.block_hash)?;
 
 		// connect out-of-order chunks and verify chain integrity.
-		self.secondary.finalize(engine)?;
+		self.secondary.finalize()?;
 
 		if let Some(writer) = self.writer {
 			writer.finish(self.manifest)?;
 		}
 
 		self.guard.disarm();
+		trace!(target: "snapshot", "restoration finalised correctly");
 		Ok(())
 	}
 
@@ -337,16 +338,6 @@ impl Service {
 		dir
 	}
 
-	// replace one the client's database with our own.
-	fn replace_client_db(&self) -> Result<(), Error> {
-		let migrated_blocks = self.migrate_blocks()?;
-		info!(target: "snapshot", "Migrated {} ancient blocks", migrated_blocks);
-
-		let rest_db = self.restoration_db();
-		self.client.restore_db(&*rest_db.to_string_lossy())?;
-		Ok(())
-	}
-
 	// Migrate the blocks in the current DB into the new chain
 	fn migrate_blocks(&self) -> Result<usize, Error> {
 		// Count the number of migrated blocks
@@ -361,11 +352,27 @@ impl Service {
 
 		// The old database looks like this:
 		// [genesis, best_ancient_block] ... [first_block, best_block]
-		// If we are fully synced neither `best_ancient_block` nor `first_block` is set, and we can assume that the whole range from [genesis, best_block] is imported.
-		// The new database only contains the tip of the chain ([first_block, best_block]),
+		// If we are fully synced neither `best_ancient_block` nor `first_block` is set, and we can
+		// assume that the whole range from [genesis, best_block] is imported.
+		// The new database only contains the tip of the chain ([new_first_block, new_best_block]),
 		// so the useful set of blocks is defined as:
 		// [0 ... min(new.first_block, best_ancient_block or best_block)]
+		//
+		// If, for whatever reason, the old db does not have ancient blocks (i.e.
+		// `best_ancient_block` is `None`) AND a non-zero `first_block`, such that the old db looks
+		// like [old_first_block..old_best_block] (which may or may not partially overlap with
+		// [new_first_block..new_best_block]) we do the conservative thing and do not migrate the
+		// old blocks.
 		let find_range = || -> Option<(H256, H256)> {
+			// TODO: In theory, if the current best_block is > new first_block (i.e. they overlap)
+			//  we could salvage them but what if there's been a re-org at the boundary and the two
+			//  chains do not match anymore? Would it actually work?
+			if cur_chain_info.ancient_block_number.is_none() && cur_chain_info.first_block_number.unwrap_or(0) > 0 {
+				warn!(target: "blockchain", "blocks in the current DB do not stretch back to genesis; can't salvage them into the new DB. In current DB first block : {:?}/#{:?}, best block: {:?}, #{:?}",
+					cur_chain_info.first_block_hash, cur_chain_info.first_block_number,
+					cur_chain_info.best_block_number, cur_chain_info.best_block_hash);
+				return None;
+			}
 			let next_available_from = next_chain_info.first_block_number?;
 			let cur_available_to = cur_chain_info.ancient_block_number.unwrap_or(cur_chain_info.best_block_number);
 
@@ -375,10 +382,11 @@ impl Service {
 				return None;
 			}
 
-			trace!(target: "snapshot", "Trying to import ancient blocks until {}", highest_block_num);
+			trace!(target: "snapshot", "Trying to import ancient blocks until {}. First block in new chain=#{}, first block in old chain=#{:?}, best block in old chain=#{}", highest_block_num,
+				next_available_from, cur_chain_info.first_block_number, cur_chain_info.best_block_number);
 
 			// Here we start from the highest block number and go backward to 0,
-			// thus starting at `highest_block_num` and targetting `0`.
+			// thus starting at `highest_block_num` and targeting `0`.
 			let target_hash = self.client.block_hash(BlockId::Number(0))?;
 			let start_hash = self.client.block_hash(BlockId::Number(highest_block_num))?;
 
@@ -398,7 +406,10 @@ impl Service {
 				return Ok(count);
 			}
 
-			let block = self.client.block(BlockId::Hash(parent_hash)).ok_or(::snapshot::error::Error::UnlinkedAncientBlockChain)?;
+			let block = self.client.block(BlockId::Hash(parent_hash)).ok_or_else(|| {
+				error!(target: "snapshot", "migrate_blocks: did not find block from parent_hash={} (start_hash={})", parent_hash, start_hash);
+				::snapshot::error::Error::UnlinkedAncientBlockChain(parent_hash)
+			})?;
 			parent_hash = block.parent_hash();
 
 			let block_number = block.number();
@@ -412,7 +423,11 @@ impl Service {
 					next_chain.insert_unordered_block(&mut batch, block, block_receipts, Some(parent_total_difficulty), false, true);
 					count += 1;
 				},
-				_ => break,
+				_ => {
+					error!(target: "snapshot", "migrate_blocks: failed to find receipts and parent total difficulty. Block #{}, parent_hash={:?}, parent_total_difficulty={:?}",
+						block_number, parent_hash, parent_total_difficulty);
+					break
+				},
 			}
 
 			// Writing changes to DB and logging every now and then
@@ -435,7 +450,11 @@ impl Service {
 
 		// We couldn't reach the targeted hash
 		if parent_hash != target_hash {
-			return Err(::snapshot::error::Error::UnlinkedAncientBlockChain.into());
+			error!(target: "snapshot", "migrate_blocks: could not reach the target_hash, parent_hash={:?}, target_hash={:?}, start_hash={:?}, ancient_block_number={:?}, best_block_number={:?}",
+				parent_hash, target_hash, start_hash,
+				cur_chain_info.ancient_block_number, cur_chain_info.best_block_number,
+			);
+			return Err(::snapshot::error::Error::UnlinkedAncientBlockChain(parent_hash).into());
 		}
 
 		// Update best ancient block in the Next Chain
@@ -549,6 +568,8 @@ impl Service {
 
 		*self.status.lock() = RestorationStatus::Initializing {
 			chunks_done: 0,
+			state_chunks: manifest.state_hashes.len() as u32,
+			block_chunks: manifest.block_hashes.len() as u32,
 		};
 
 		fs::create_dir_all(&rest_dir)?;
@@ -563,7 +584,7 @@ impl Service {
 			manifest: manifest.clone(),
 			pruning: self.pruning,
 			db: self.restoration_db_handler.open(&rest_db)?,
-			writer: writer,
+			writer,
 			genesis: &self.genesis_block,
 			guard: Guard::new(rest_db),
 			engine: &*self.engine,
@@ -654,15 +675,20 @@ impl Service {
 	// lead to deadlock.
 	fn finalize_restoration(&self, rest: &mut Option<Restoration>) -> Result<(), Error> {
 		trace!(target: "snapshot", "finalizing restoration");
+		*self.status.lock() = RestorationStatus::Finalizing;
 
 		let recover = rest.as_ref().map_or(false, |rest| rest.writer.is_some());
 
 		// destroy the restoration before replacing databases and snapshot.
 		rest.take()
-			.map(|r| r.finalize(&*self.engine))
+			.map(|r| r.finalize())
 			.unwrap_or(Ok(()))?;
 
-		self.replace_client_db()?;
+		let migrated_blocks = self.migrate_blocks()?;
+		info!(target: "snapshot", "Migrated {} ancient blocks", migrated_blocks);
+
+		// replace the Client's database with the new one (restart the Client).
+		self.client.restore_db(&*self.restoration_db().to_string_lossy())?;
 
 		if recover {
 			let mut reader = self.reader.write();
@@ -695,8 +721,9 @@ impl Service {
 			Ok(()) |
 			Err(Error::Snapshot(SnapshotError::RestorationAborted)) => (),
 			Err(e) => {
+				// TODO: after this we're sometimes deadlocked
 				warn!("Encountered error during snapshot restoration: {}", e);
-				*self.restoration.lock() = None;
+				self.abort_restore();
 				*self.status.lock() = RestorationStatus::Failed;
 				let _ = fs::remove_dir_all(self.restoration_dir());
 			}
@@ -707,8 +734,8 @@ impl Service {
 	fn feed_chunk_with_restoration(&self, restoration: &mut Option<Restoration>, hash: H256, chunk: &[u8], is_state: bool) -> Result<(), Error> {
 		let (result, db) = {
 			match self.status() {
-				RestorationStatus::Inactive | RestorationStatus::Failed => {
-					trace!(target: "snapshot", "Tried to restore chunk {:x} while inactive or failed", hash);
+				RestorationStatus::Inactive | RestorationStatus::Failed | RestorationStatus::Finalizing => {
+					trace!(target: "snapshot", "Tried to restore chunk {:x} while inactive, failed or finalizing", hash);
 					return Ok(());
 				},
 				RestorationStatus::Ongoing { .. } | RestorationStatus::Initializing { .. } => {
@@ -803,7 +830,7 @@ impl SnapshotService for Service {
 		let mut cur_status = self.status.lock();
 
 		match *cur_status {
-			RestorationStatus::Initializing { ref mut chunks_done } => {
+			RestorationStatus::Initializing { ref mut chunks_done, .. } => {
 				*chunks_done = self.state_chunks.load(Ordering::SeqCst) as u32 +
 					self.block_chunks.load(Ordering::SeqCst) as u32;
 			}

ethcore/src/snapshot/tests/proof_of_work.rs

@@ -93,7 +93,7 @@ fn chunk_and_restore(amount: u64) {
 		rebuilder.feed(&chunk, engine.as_ref(), &flag).unwrap();
 	}
 
-	rebuilder.finalize(engine.as_ref()).unwrap();
+	rebuilder.finalize().unwrap();
 	drop(rebuilder);
 
 	// and test it.

ethcore/sync/src/chain/handler.rs

@@ -256,7 +256,7 @@ impl SyncHandler {
 				return Err(DownloaderImportError::Invalid);
 			}
 			match io.chain().block_status(BlockId::Hash(hash.clone())) {
-				BlockStatus::InChain  => {
+				BlockStatus::InChain => {
 					trace!(target: "sync", "New block hash already in chain {:?}", hash);
 				},
 				BlockStatus::Queued => {
@@ -529,10 +529,14 @@ impl SyncHandler {
 				sync.snapshot.clear();
 				return Ok(());
 			},
-			RestorationStatus::Initializing  { .. } => {
+			RestorationStatus::Initializing { .. } => {
 				trace!(target: "warp", "{}: Snapshot restoration is initializing", peer_id);
 				return Ok(());
 			}
+			RestorationStatus::Finalizing => {
+				trace!(target: "warp", "{}: Snapshot finalizing restoration", peer_id);
+				return Ok(());
+			}
 			RestorationStatus::Ongoing { .. } => {
 				trace!(target: "sync", "{}: Snapshot restoration is ongoing", peer_id);
 			},

ethcore/sync/src/chain/mod.rs

@@ -1210,7 +1210,7 @@ impl ChainSync {
 				RestorationStatus::Inactive | RestorationStatus::Failed => {
 					self.set_state(SyncState::SnapshotWaiting);
 				},
-				RestorationStatus::Initializing { .. } | RestorationStatus::Ongoing { .. } => (),
+				RestorationStatus::Initializing { .. } | RestorationStatus::Ongoing { .. } | RestorationStatus::Finalizing => (),
 			},
 			SyncState::SnapshotWaiting => {
 				match io.snapshot_service().status() {
@@ -1221,6 +1221,9 @@ impl ChainSync {
 					RestorationStatus::Initializing { .. } => {
 						trace!(target:"sync", "Snapshot restoration is initializing");
 					},
+					RestorationStatus::Finalizing { .. } => {
+						trace!(target:"sync", "Snapshot finalizing restoration");
+					},
 					RestorationStatus::Ongoing { state_chunks_done, block_chunks_done, .. } => {
 						if !self.snapshot.is_complete() && self.snapshot.done_chunks() - (state_chunks_done + block_chunks_done) as usize <= MAX_SNAPSHOT_CHUNKS_DOWNLOAD_AHEAD {
 							trace!(target:"sync", "Resuming snapshot sync");