From 5da8da68cc21edb7416f5b575e2bfda8a5dd88cf Mon Sep 17 00:00:00 2001 From: David Date: Mon, 10 Jun 2019 18:58:14 +0200 Subject: [PATCH] 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 | 24 +++++++++++++++---- .../src/engines/authority_round/finality.rs | 12 ++++++++-- ethcore/src/engines/authority_round/mod.rs | 8 +++---- ethcore/src/verification/verifier.rs | 2 +- 4 files changed, 34 insertions(+), 12 deletions(-) diff --git a/ethcore/blockchain/src/blockchain.rs b/ethcore/blockchain/src/blockchain.rs index b528334ca..7cf6b12dd 100644 --- a/ethcore/blockchain/src/blockchain.rs +++ b/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 { // 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), } } diff --git a/ethcore/src/engines/authority_round/finality.rs b/ethcore/src/engines/authority_round/finality.rs index af57278c9..e88458d81 100644 --- a/ethcore/src/engines/authority_round/finality.rs +++ b/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
) -> 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
) -> Result, 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) diff --git a/ethcore/src/engines/authority_round/mod.rs b/ethcore/src/engines/authority_round/mod.rs index 0942c0881..8bf838d2d 100644 --- a/ethcore/src/engines/authority_round/mod.rs +++ b/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(()) diff --git a/ethcore/src/verification/verifier.rs b/ethcore/src/verification/verifier.rs index 76eb60b9a..f7221dae8 100644 --- a/ethcore/src/verification/verifier.rs +++ b/ethcore/src/verification/verifier.rs @@ -38,6 +38,6 @@ pub trait Verifier: 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>; }