Stop breaking out of loop if a non-canonical hash is found (#10729)

* Stop breaking out of loop if a non-canonical hash is found

* include expected hash in log msg

* More logging

* Scope

* Syntax

* Log in blank RollingFinality
Escalate bad proposer to warning

* More readable code

* Extensive logging on unexpected non-canonical hash

* Wording

ethcore/blockchain/src/blockchain.rs

@@ -963,6 +963,7 @@ impl BlockChain {
 	/// Iterate over all epoch transitions.
 	/// This will only return transitions within the canonical chain.
 	pub fn epoch_transitions(&self) -> EpochTransitionIter {
+		trace!(target: "blockchain", "Iterating over all epoch transitions");
 		let iter = self.db.key_value().iter_from_prefix(db::COL_EXTRA, &EPOCH_KEY_PREFIX[..]);
 		EpochTransitionIter {
 			chain: self,
@@ -988,7 +989,9 @@ impl BlockChain {
 	pub fn epoch_transition_for(&self, parent_hash: H256) -> Option<EpochTransition> {
 		// slow path: loop back block by block
 		for hash in self.ancestry_iter(parent_hash)? {
+			trace!(target: "blockchain", "Got parent hash {} from ancestry_iter", hash);
 			let details = self.block_details(&hash)?;
+			trace!(target: "blockchain", "Block #{}: Got block details", details.number);
 
 			// look for transition in database.
 			if let Some(transition) = self.epoch_transition(details.number, hash) {
@@ -1000,11 +1003,22 @@ impl BlockChain {
 			//
 			// if `block_hash` is canonical it will only return transitions up to
 			// the parent.
-			if self.block_hash(details.number)? == hash {
-				return self.epoch_transitions()
-					.map(|(_, t)| t)
-					.take_while(|t| t.block_number <= details.number)
-					.last()
+			match self.block_hash(details.number) {
+				Some(h) if h == hash => {
+					return self.epoch_transitions()
+						.map(|(_, t)| t)
+						.take_while(|t| t.block_number <= details.number)
+						.last()
+				},
+				Some(h) => {
+					warn!(target: "blockchain", "Block #{}: Found non-canonical block hash {} (expected {})", details.number, h, hash);
+
+					trace!(target: "blockchain", "Block #{} Mismatched hashes. Ancestor {} != Own {} – Own block #{}", details.number, hash, h, self.block_number(&h).unwrap_or_default() );
+					trace!(target: "blockchain", "      Ancestor {}: #{:#?}", hash, self.block_details(&hash));
+					trace!(target: "blockchain", "      Own      {}: #{:#?}", h, self.block_details(&h));
+
+				},
+				None => trace!(target: "blockchain", "Block #{}: hash {} not found in cache or DB", details.number, hash),
 			}
 		}
 

ethcore/src/engines/authority_round/finality.rs

@@ -39,6 +39,7 @@ pub struct RollingFinality {
 impl RollingFinality {
 	/// Create a blank finality checker under the given validator set.
 	pub fn blank(signers: Vec<Address>) -> Self {
+		trace!(target: "finality", "Instantiating blank RollingFinality with {} signers: {:?}", signers.len(), signers);
 		RollingFinality {
 			headers: VecDeque::new(),
 			signers: SimpleList::new(signers),
@@ -110,7 +111,14 @@ impl RollingFinality {
 	/// Returns a list of all newly finalized headers.
 	// TODO: optimize with smallvec.
 	pub fn push_hash(&mut self, head: H256, signers: Vec<Address>) -> Result<Vec<H256>, UnknownValidator> {
-		if signers.iter().any(|s| !self.signers.contains(s)) { return Err(UnknownValidator) }
+		// TODO: seems bad to iterate over signers twice like this.
+		//       Can do the work in a single loop and call `clear()` if an unknown validator was found?
+		for their_signer in signers.iter() {
+			if !self.signers.contains(their_signer) {
+				warn!(target: "finality",  "Unknown validator: {}", their_signer);
+				return Err(UnknownValidator)
+			}
+		}
 
 		for signer in signers.iter() {
 			*self.sign_count.entry(*signer).or_insert(0) += 1;
@@ -141,7 +149,7 @@ impl RollingFinality {
 			}
 		}
 
-		trace!(target: "finality", "Blocks finalized by {:?}: {:?}", head, newly_finalized);
+		trace!(target: "finality", "{} Blocks finalized by {:?}: {:?}", newly_finalized.len(), head, newly_finalized);
 
 		self.last_pushed = Some(head);
 		Ok(newly_finalized)

ethcore/src/engines/authority_round/mod.rs

@@ -247,7 +247,7 @@ impl EpochManager {
 			None => {
 				// this really should never happen unless the block passed
 				// hasn't got a parent in the database.
-				debug!(target: "engine", "No genesis transition found.");
+				warn!(target: "engine", "No genesis transition found.");
 				return false;
 			}
 		};
@@ -280,8 +280,8 @@ impl EpochManager {
 		true
 	}
 
-	// note new epoch hash. this will force the next block to re-load
-	// the epoch set
+	// Note new epoch hash. This will force the next block to re-load
+	// the epoch set.
 	// TODO: optimize and don't require re-loading after epoch change.
 	fn note_new_epoch(&mut self) {
 		self.force = true;
@@ -614,7 +614,7 @@ fn verify_external(header: &Header, validators: &ValidatorSet, empty_steps_trans
 	};
 
 	if is_invalid_proposer {
-		trace!(target: "engine", "verify_block_external: bad proposer for step: {}", header_step);
+		warn!(target: "engine", "verify_block_external: bad proposer for step: {}", header_step);
 		Err(EngineError::NotProposer(Mismatch { expected: correct_proposer, found: *header.author() }))?
 	} else {
 		Ok(())

ethcore/src/verification/verifier.rs

@@ -38,6 +38,6 @@ pub trait Verifier<C>: Send + Sync
 
 	/// Do a final verification check for an enacted header vs its expected counterpart.
 	fn verify_block_final(&self, expected: &Header, got: &Header) -> Result<(), Error>;
-	/// Verify a block, inspecing external state.
+	/// Verify a block, inspecting external state.
 	fn verify_block_external(&self, header: &Header, engine: &EthEngine) -> Result<(), Error>;
 }