From 825c7990f29514d699e22c6e78f73710e53e983d Mon Sep 17 00:00:00 2001 From: David Date: Tue, 25 Jun 2019 13:15:00 +0200 Subject: [PATCH] Log validator set changes in EpochManager (#10734) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 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 * Check validator set size: warn if 1 or even number * More readable code * Use SimpleList::new * Extensive logging on unexpected non-canonical hash * Wording * wip * Update ethcore/blockchain/src/blockchain.rs Co-Authored-By: Tomasz Drwięga * Improved logging, address grumbles * Update ethcore/src/engines/validator_set/simple_list.rs Co-Authored-By: Luke Schoen * Report benign misbehaviour iff currently a validator * Report malicious behaviour iff we're a validator * Escalate to warning and fix wording * Test reporting behaviour Don't require node to be part of the validator set to report malicious behaviour * Include missing parent hash in MissingParent error * Update ethcore/src/engines/validator_set/simple_list.rs Co-Authored-By: Luke Schoen * cleanup * On second thought non-validators are allowed to report * cleanup * remove dead code --- ethcore/src/engines/authority_round/mod.rs | 97 +++++++++++++------ ethcore/src/engines/mod.rs | 4 +- .../src/engines/validator_set/simple_list.rs | 5 +- ethcore/src/engines/validator_set/test.rs | 12 ++- 4 files changed, 78 insertions(+), 40 deletions(-) diff --git a/ethcore/src/engines/authority_round/mod.rs b/ethcore/src/engines/authority_round/mod.rs index 11fab75ab..44c10b4c2 100644 --- a/ethcore/src/engines/authority_round/mod.rs +++ b/ethcore/src/engines/authority_round/mod.rs @@ -235,6 +235,8 @@ impl EpochManager { self.force = false; debug!(target: "engine", "Zooming to epoch after block {}", hash); + trace!(target: "engine", "Current validator set: {:?}", self.validators()); + // epoch_transition_for can be an expensive call, but in the absence of // forks it will only need to be called for the block directly after @@ -255,7 +257,7 @@ impl EpochManager { let (signal_number, set_proof, _) = destructure_proofs(&last_transition.proof) .expect("proof produced by this engine; therefore it is valid; qed"); - trace!(target: "engine", "extracting epoch set for epoch ({}, {}) signalled at #{}", + trace!(target: "engine", "extracting epoch validator set for epoch ({}, {}) signalled at #{}", last_transition.block_number, last_transition.block_hash, signal_number); let first = signal_number == 0; @@ -266,7 +268,12 @@ impl EpochManager { set_proof, ) .ok() - .map(|(list, _)| list.into_inner()) + .map(|(list, _)| { + trace!(target: "engine", "Updating finality checker with new validator set extracted from epoch ({}, {}): {:?}", + last_transition.block_number, last_transition.block_hash, &list); + + list.into_inner() + }) .expect("proof produced by this engine; therefore it is valid; qed"); self.finality_checker = RollingFinality::blank(epoch_set); @@ -698,7 +705,7 @@ impl AuthorityRound { empty_steps_transition: our_params.empty_steps_transition, maximum_empty_steps: our_params.maximum_empty_steps, strict_empty_steps_transition: our_params.strict_empty_steps_transition, - machine: machine, + machine, }); // Do not initialize timeouts for tests. @@ -729,7 +736,7 @@ impl AuthorityRound { if !epoch_manager.zoom_to_after(&*client, &self.machine, &*self.validators, *header.parent_hash()) { debug!(target: "engine", "Unable to zoom to epoch."); - return Err(EngineError::MissingParent.into()) + return Err(EngineError::MissingParent(*header.parent_hash()).into()) } (CowLike::Owned(epoch_manager.validators().clone()), epoch_manager.epoch_transition_number) @@ -806,7 +813,7 @@ impl AuthorityRound { return; } - if let (true, Some(me)) = (current_step > parent_step + 1, self.signer.read().as_ref().map(|s| s.address())) { + if let (true, Some(me)) = (current_step > parent_step + 1, self.address()) { debug!(target: "engine", "Author {} built block with step gap. current step: {}, parent step: {}", header.author(), current_step, parent_step); let mut reported = HashSet::new(); @@ -816,9 +823,13 @@ impl AuthorityRound { if skipped_primary != me { // Stop reporting once validators start repeating. if !reported.insert(skipped_primary) { break; } + trace!(target: "engine", "Reporting benign misbehaviour (cause: skipped step) at block #{}, epoch set number {}. Own address: {}", + header.number(), set_number, me); self.validators.report_benign(&skipped_primary, set_number, header.number()); - } - } + } else { + trace!(target: "engine", "Primary that skipped is self, not self-reporting. Own address: {}", me); + } + } } } @@ -884,6 +895,10 @@ impl AuthorityRound { let finalized = epoch_manager.finality_checker.push_hash(chain_head.hash(), vec![*chain_head.author()]); finalized.unwrap_or_default() } + + fn address(&self) -> Option
{ + self.signer.read().as_ref().map(|s| s.address() ) + } } fn unix_now() -> Duration { @@ -1283,13 +1298,16 @@ impl Engine for AuthorityRound { // This check runs in Phase 1 where there is no guarantee that the parent block is // already imported, therefore the call to `epoch_set` may fail. In that case we // won't report the misbehavior but this is not a concern because: - // - Only authorities can report and it's expected that they'll be up-to-date and - // importing, therefore the parent header will most likely be available + // - Authorities will have a signing key available to report and it's expected that + // they'll be up-to-date and importing, therefore the parent header will most likely + // be available // - Even if you are an authority that is syncing the chain, the contract will most // likely ignore old reports // - This specific check is only relevant if you're importing (since it checks // against wall clock) - if let Ok((_, set_number)) = self.epoch_set(header) { + if let Ok((_, set_number)) = self.epoch_set(header) { + trace!(target: "engine", "Reporting benign misbehaviour (cause: InvalidSeal) at block #{}, epoch set number {}. Own address: {}", + header.number(), set_number, self.address().unwrap_or_default()); self.validators.report_benign(header.author(), set_number, header.number()); } @@ -1310,7 +1328,7 @@ impl Engine for AuthorityRound { // Ensure header is from the step after parent. if step == parent_step || (header.number() >= self.validate_step_transition && step <= parent_step) { - trace!(target: "engine", "Multiple blocks proposed for step {}.", parent_step); + warn!(target: "engine", "Multiple blocks proposed for step {}.", parent_step); self.validators.report_malicious(header.author(), set_number, header.number(), Default::default()); Err(EngineError::DoubleVote(*header.author()))?; @@ -1360,6 +1378,8 @@ impl Engine for AuthorityRound { match validate_empty_steps() { Ok(len) => len, Err(err) => { + trace!(target: "engine", "Reporting benign misbehaviour (cause: invalid empty steps) at block #{}, epoch set number {}. Own address: {}", + header.number(), set_number, self.address().unwrap_or_default()); self.validators.report_benign(header.author(), set_number, header.number()); return Err(err); }, @@ -1389,6 +1409,8 @@ impl Engine for AuthorityRound { let res = verify_external(header, &*validators, self.empty_steps_transition); match res { Err(Error::Engine(EngineError::NotProposer(_))) => { + trace!(target: "engine", "Reporting benign misbehaviour (cause: block from incorrect proposer) at block #{}, epoch set number {}. Own address: {}", + header.number(), set_number, self.address().unwrap_or_default()); self.validators.report_benign(header.author(), set_number, header.number()); }, Ok(_) => { @@ -1619,7 +1641,7 @@ mod tests { use error::Error; use super::{AuthorityRoundParams, AuthorityRound, EmptyStep, SealedEmptyStep, calculate_score}; - fn aura(f: F) -> Arc where + fn build_aura(f: F) -> Arc where F: FnOnce(&mut AuthorityRoundParams), { let mut params = AuthorityRoundParams { @@ -1641,7 +1663,6 @@ mod tests { // mutate aura params f(&mut params); - // create engine let mut c_params = ::spec::CommonParams::default(); c_params.gas_limit_bound_divisor = 5.into(); @@ -1821,9 +1842,19 @@ mod tests { #[test] fn reports_skipped() { + let _ = ::env_logger::try_init(); + + let validator1 = Address::from_low_u64_be(1); + let validator2 = Address::from_low_u64_be(2); let last_benign = Arc::new(AtomicUsize::new(0)); - let aura = aura(|p| { - p.validators = Box::new(TestSet::new(Default::default(), last_benign.clone())); + + let aura = build_aura(|p| { + let validator_set = TestSet::new( + Default::default(), + last_benign.clone(), + vec![validator1, validator2], + ); + p.validators = Box::new(validator_set); }); let mut parent_header: Header = Header::default(); @@ -1838,7 +1869,11 @@ mod tests { assert!(aura.verify_block_family(&header, &parent_header).is_ok()); assert_eq!(last_benign.load(AtomicOrdering::SeqCst), 0); - aura.set_signer(Box::new((Arc::new(AccountProvider::transient_provider()), Default::default(), "".into()))); + aura.set_signer(Box::new(( + Arc::new(AccountProvider::transient_provider()), + validator2, + "".into(), + ))); // Do not report on steps skipped between genesis and first block. header.set_number(1); @@ -1853,7 +1888,7 @@ mod tests { #[test] fn test_uncles_transition() { - let aura = aura(|params| { + let aura = build_aura(|params| { params.maximum_uncle_count_transition = 1; }); @@ -1862,16 +1897,16 @@ mod tests { assert_eq!(aura.maximum_uncle_count(100), 0); } - #[test] - #[should_panic(expected="counter is too high")] - fn test_counter_increment_too_high() { - use super::Step; - let step = Step { - calibrate: false, - inner: AtomicUsize::new(::std::usize::MAX), - duration: 1, - }; - step.increment(); + #[test] + #[should_panic(expected="counter is too high")] + fn test_counter_increment_too_high() { + use super::Step; + let step = Step { + calibrate: false, + inner: AtomicUsize::new(::std::usize::MAX), + duration: 1, + }; + step.increment(); } #[test] @@ -1889,7 +1924,7 @@ mod tests { #[test] #[should_panic(expected="authority_round: step duration can't be zero")] fn test_step_duration_zero() { - aura(|params| { + build_aura(|params| { params.step_duration = 0; }); } @@ -2281,7 +2316,7 @@ mod tests { #[test] fn test_empty_steps() { - let engine = aura(|p| { + let engine = build_aura(|p| { p.step_duration = 4; p.empty_steps_transition = 0; p.maximum_empty_steps = 0; @@ -2314,7 +2349,7 @@ mod tests { fn should_reject_duplicate_empty_steps() { // given let (_spec, tap, accounts) = setup_empty_steps(); - let engine = aura(|p| { + let engine = build_aura(|p| { p.validators = Box::new(SimpleList::new(accounts.clone())); p.step_duration = 4; p.empty_steps_transition = 0; @@ -2351,7 +2386,7 @@ mod tests { fn should_reject_empty_steps_out_of_order() { // given let (_spec, tap, accounts) = setup_empty_steps(); - let engine = aura(|p| { + let engine = build_aura(|p| { p.validators = Box::new(SimpleList::new(accounts.clone())); p.step_duration = 4; p.empty_steps_transition = 0; diff --git a/ethcore/src/engines/mod.rs b/ethcore/src/engines/mod.rs index e0db2181e..da49e21ea 100644 --- a/ethcore/src/engines/mod.rs +++ b/ethcore/src/engines/mod.rs @@ -90,7 +90,7 @@ pub enum EngineError { /// Requires signer ref, but none registered. RequiresSigner, /// Missing Parent Epoch - MissingParent, + MissingParent(H256), /// Checkpoint is missing CliqueMissingCheckpoint(H256), /// Missing vanity data @@ -139,7 +139,7 @@ impl fmt::Display for EngineError { RequiresClient => format!("Call requires client but none registered"), RequiresSigner => format!("Call requires signer but none registered"), InvalidEngine => format!("Invalid engine specification or implementation"), - MissingParent => format!("Parent Epoch is missing from database"), + MissingParent(ref hash) => format!("Parent Epoch is missing from database: {}", hash), }; f.write_fmt(format_args!("Engine error ({})", msg)) diff --git a/ethcore/src/engines/validator_set/simple_list.rs b/ethcore/src/engines/validator_set/simple_list.rs index 958bda202..80a34268e 100644 --- a/ethcore/src/engines/validator_set/simple_list.rs +++ b/ethcore/src/engines/validator_set/simple_list.rs @@ -36,9 +36,8 @@ impl SimpleList { let validator_count = validators.len(); if validator_count == 1 { warn!(target: "engine", "Running AuRa with a single validator implies instant finality. Use a database?"); - } - if validator_count % 2 == 0 { - warn!(target: "engine", "Running AuRa with an even number of validators is not recommended (risk of network split)."); + } else if validator_count != 0 && validator_count % 2 == 0 { + warn!(target: "engine", "Running AuRa with an even number of validators ({}) is not recommended (risk of network split).", validator_count); } SimpleList { validators } } diff --git a/ethcore/src/engines/validator_set/test.rs b/ethcore/src/engines/validator_set/test.rs index c81259f5b..b82bcfe12 100644 --- a/ethcore/src/engines/validator_set/test.rs +++ b/ethcore/src/engines/validator_set/test.rs @@ -30,7 +30,7 @@ use machine::{AuxiliaryData, Call, EthereumMachine}; use super::{ValidatorSet, SimpleList}; /// Set used for testing with a single validator. -#[derive(MallocSizeOf)] +#[derive(MallocSizeOf, Debug)] pub struct TestSet { validator: SimpleList, #[ignore_malloc_size_of = "zero sized"] @@ -41,14 +41,18 @@ pub struct TestSet { impl Default for TestSet { fn default() -> Self { - TestSet::new(Default::default(), Default::default()) + TestSet::new( + Default::default(), + Default::default(), + vec![Address::from_str("7d577a597b2742b498cb5cf0c26cdcd726d39e6e").unwrap()] + ) } } impl TestSet { - pub fn new(last_malicious: Arc, last_benign: Arc) -> Self { + pub fn new(last_malicious: Arc, last_benign: Arc, validators: Vec
) -> Self { TestSet { - validator: SimpleList::new(vec![Address::from_str("7d577a597b2742b498cb5cf0c26cdcd726d39e6e").unwrap()]), + validator: SimpleList::new(validators), last_malicious, last_benign, }