Improve logging and cleanup in miner around block sealing

ethcore/blockchain/src/blockchain.rs

@@ -755,8 +755,8 @@ impl BlockChain {
 		Some(TreeRoute {
 			blocks: from_branch,
 			ancestor: current_from,
-			index: index,
-			is_from_route_finalized: is_from_route_finalized,
+			index,
+			is_from_route_finalized,
 		})
 	}
 

ethcore/src/block.rs

@@ -178,8 +178,7 @@ impl<'x> OpenBlock<'x> {
 	) -> Result<Self, Error> {
 		let number = parent.number() + 1;
 		let state = State::from_existing(db, parent.state_root().clone(), engine.account_start_nonce(number), factories)?;
-
-		let mut r = OpenBlock { block: ExecutedBlock::new(state, last_hashes, tracing), engine, parent: parent.clone() };
+		let mut r = OpenBlock { block: ExecutedBlock::new(state, last_hashes, tracing), engine, parent: parent.clone()};
 
 		r.block.header.set_parent_hash(parent.hash());
 		r.block.header.set_number(number);

ethcore/src/client/client.rs

@@ -473,7 +473,16 @@ impl Importer {
 	//
 	// The header passed is from the original block data and is sealed.
 	// TODO: should return an error if ImportRoute is none, issue #9910
-	fn commit_block<B>(&self, block: B, header: &Header, block_data: encoded::Block, pending: Option<PendingTransition>, client: &Client) -> ImportRoute where B: Drain {
+	fn commit_block<B>(
+		&self,
+		block: B,
+		header: &Header,
+		block_data: encoded::Block,
+		pending: Option<PendingTransition>,
+		client: &Client
+	) -> ImportRoute
+		where B: Drain
+	{
 		let hash = &header.hash();
 		let number = header.number();
 		let parent = header.parent_hash();
@@ -499,18 +508,17 @@ impl Importer {
 		};
 
 		let best = {
-			let hash = best_hash;
-			let header = chain.block_header_data(&hash)
+			let header = chain.block_header_data(&best_hash)
 				.expect("Best block is in the database; qed")
 				.decode()
 				.expect("Stored block header is valid RLP; qed");
-			let details = chain.block_details(&hash)
+			let details = chain.block_details(&best_hash)
 				.expect("Best block is in the database; qed");
 
 			ExtendedHeader {
 				parent_total_difficulty: details.total_difficulty - *header.difficulty(),
 				is_finalized: details.is_finalized,
-				header: header,
+				header,
 			}
 		};
 
@@ -548,7 +556,7 @@ impl Importer {
 		}).collect();
 
 		let route = chain.insert_block(&mut batch, block_data, receipts.clone(), ExtrasInsert {
-			fork_choice: fork_choice,
+			fork_choice,
 			is_finalized,
 		});
 
@@ -2410,19 +2418,19 @@ impl ImportSealedBlock for Client {
 			let _import_lock = self.importer.import_lock.lock();
 			trace_time!("import_sealed_block");
 
-			let block_data = block.rlp_bytes();
+			let block_bytes = block.rlp_bytes();
 
 			let pending = self.importer.check_epoch_end_signal(
 				&header,
-				&block_data,
+				&block_bytes,
 				&block.receipts,
 				block.state.db(),
 				self
 			)?;
 			let route = self.importer.commit_block(
 				block,
 				&header,
-				encoded::Block::new(block_data),
+				encoded::Block::new(block_bytes),
 				pending,
 				self
 			);

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.
-				warn!(target: "engine", "No genesis transition found.");
+				warn!(target: "engine", "No genesis transition found. Block hash {} does not have a parent in the DB", hash);
 				return false;
 			}
 		};
@@ -570,7 +570,7 @@ fn header_empty_steps_signers(header: &Header, empty_steps_transition: u64) -> R
 
 fn step_proposer(validators: &dyn ValidatorSet, bh: &H256, step: u64) -> Address {
 	let proposer = validators.get(bh, step as usize);
-	trace!(target: "engine", "Fetched proposer for step {}: {}", step, proposer);
+	trace!(target: "engine", "step_proposer: Fetched proposer for step {}: {}", step, proposer);
 	proposer
 }
 
@@ -823,8 +823,8 @@ 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);
+					trace!(target: "engine", "Reporting benign misbehaviour (cause: skipped step) at block #{}, epoch set number {}, step proposer={:#x}. Own address: {}",
+						header.number(), set_number, skipped_primary, 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);
@@ -1110,25 +1110,30 @@ impl Engine for AuthorityRound {
 
 		// filter messages from old and future steps and different parents
 		let empty_steps = if header.number() >= self.empty_steps_transition {
-			self.empty_steps(parent_step.into(), step.into(), *header.parent_hash())
+			self.empty_steps(parent_step, step, *header.parent_hash())
 		} else {
 			Vec::new()
 		};
 
-		let expected_diff = calculate_score(parent_step, step.into(), empty_steps.len().into());
+		let expected_diff = calculate_score(parent_step, step, empty_steps.len());
 
 		if header.difficulty() != &expected_diff {
 			debug!(target: "engine", "Aborting seal generation. The step or empty_steps have changed in the meantime. {:?} != {:?}",
 				   header.difficulty(), expected_diff);
 			return Seal::None;
 		}
 
-		if parent_step > step.into() {
+		if parent_step > step {
 			warn!(target: "engine", "Aborting seal generation for invalid step: {} > {}", parent_step, step);
 			return Seal::None;
+		} else if parent_step == step {
+			// this is guarded against by `can_propose` unless the block was signed
+			// on the same step (implies same key) and on a different node.
+			warn!("Attempted to seal block on the same step as parent. Is this authority sealing with more than one node?");
+			return Seal::None;
 		}
 
-		let (validators, set_number) = match self.epoch_set(header) {
+		let (validators, epoch_transition_number) = match self.epoch_set(header) {
 			Err(err) => {
 				warn!(target: "engine", "Unable to generate seal: {}", err);
 				return Seal::None;
@@ -1137,13 +1142,7 @@ impl Engine for AuthorityRound {
 		};
 
 		if is_step_proposer(&*validators, header.parent_hash(), step, header.author()) {
-			// this is guarded against by `can_propose` unless the block was signed
-			// on the same step (implies same key) and on a different node.
-			if parent_step == step {
-				warn!("Attempted to seal block on the same step as parent. Is this authority sealing with more than one node?");
-				return Seal::None;
-			}
-
+			trace!(target: "engine", "generate_seal: we are step proposer for step={}, block=#{}", step, header.number());
 			// if there are no transactions to include in the block, we don't seal and instead broadcast a signed
 			// `EmptyStep(step, parent_hash)` message. If we exceed the maximum amount of `empty_step` rounds we proceed
 			// with the seal.
@@ -1152,6 +1151,7 @@ impl Engine for AuthorityRound {
 				empty_steps.len() < self.maximum_empty_steps {
 
 				if self.step.can_propose.compare_and_swap(true, false, AtomicOrdering::SeqCst) {
+					trace!(target: "engine", "generate_seal: generating empty step at step={}, block=#{}", step, header.number());
 					self.generate_empty_step(header.parent_hash());
 				}
 
@@ -1178,7 +1178,8 @@ impl Engine for AuthorityRound {
 					// report any skipped primaries between the parent block and
 					// the block we're sealing, unless we have empty steps enabled
 					if header.number() < self.empty_steps_transition {
-						self.report_skipped(header, step, parent_step, &*validators, set_number);
+						trace!(target: "engine", "generate_seal: reporting misbehaviour for step={}, block=#{}", step, header.number());
+						self.report_skipped(header, step, parent_step, &*validators, epoch_transition_number);
 					}
 
 					let mut fields = vec![
@@ -1189,7 +1190,7 @@ impl Engine for AuthorityRound {
 					if let Some(empty_steps_rlp) = empty_steps_rlp {
 						fields.push(empty_steps_rlp);
 					}
-
+					trace!(target: "engine", "generate_seal: returning Seal::Regular for step={}, block=#{}", step, header.number());
 					return Seal::Regular(fields);
 				}
 			} else {
@@ -1199,7 +1200,7 @@ impl Engine for AuthorityRound {
 			trace!(target: "engine", "generate_seal: {} not a proposer for step {}.",
 				header.author(), step);
 		}
-
+		trace!(target: "engine", "generate_seal: returning Seal::None for step={}, block=#{}", step, header.number());
 		Seal::None
 	}
 
@@ -1739,13 +1740,13 @@ mod tests {
 
 		engine.set_signer(Box::new((tap.clone(), addr1, "1".into())));
 		match engine.generate_seal(&b1, &genesis_header) {
-			Seal::None | Seal::Proposal(_) => panic!("wrong seal"),
+			Seal::None => panic!("wrong seal"),
 			Seal::Regular(_) => {
 				engine.step();
 
 				engine.set_signer(Box::new((tap.clone(), addr2, "0".into())));
 				match engine.generate_seal(&b2, &genesis_header) {
-					Seal::Regular(_) | Seal::Proposal(_) => panic!("sealed despite wrong difficulty"),
+					Seal::Regular(_) => panic!("sealed despite wrong difficulty"),
 					Seal::None => {}
 				}
 			}

ethcore/src/engines/mod.rs

@@ -156,8 +156,6 @@ impl error::Error for EngineError {
 /// Seal type.
 #[derive(Debug, PartialEq, Eq)]
 pub enum Seal {
-	/// Proposal seal; should be broadcasted, but not inserted into blockchain.
-	Proposal(Vec<Bytes>),
 	/// Regular block seal; should be part of the blockchain.
 	Regular(Vec<Bytes>),
 	/// Engine does not generate seal for this block right now.

ethcore/src/engines/validator_set/contract.rs

@@ -118,6 +118,7 @@ impl ValidatorSet for ValidatorContract {
 	}
 
 	fn report_benign(&self, address: &Address, _set_block: BlockNumber, block: BlockNumber) {
+		trace!(target: "engine", "validator set recording benign misbehaviour at block #{} by {:#x}", block, address);
 		let data = validator_report::functions::report_benign::encode_input(*address, block);
 		match self.transact(data) {
 			Ok(_) => warn!(target: "engine", "Reported benign validator misbehaviour {}", address),
@@ -162,6 +163,7 @@ mod tests {
 
 	#[test]
 	fn reports_validators() {
+		let _ = ::env_logger::try_init();
 		let tap = Arc::new(AccountProvider::transient_provider());
 		let v1 = tap.insert_account(keccak("1").into(), &"".into()).unwrap();
 		let client = generate_dummy_client_with_spec(Spec::new_validator_contract);

ethcore/src/engines/validator_set/safe_contract.rs

@@ -74,6 +74,8 @@ impl ::engines::StateDependentProof for StateProof {
 /// The validator contract should have the following interface:
 pub struct ValidatorSafeContract {
 	contract_address: Address,
+	/// The LRU cache is indexed by the parent_hash, so given a hash, the value
+	/// is the validator set valid for the blocks following that hash.
 	validators: RwLock<MemoryLruCache<H256, SimpleList>>,
 	client: RwLock<Option<Weak<dyn EngineClient>>>, // TODO [keorn]: remove
 }
@@ -471,6 +473,7 @@ mod tests {
 
 	#[test]
 	fn knows_validators() {
+		let _ = env_logger::try_init();
 		let tap = Arc::new(AccountProvider::transient_provider());
 		let s0: Secret = keccak("1").into();
 		let v0 = tap.insert_account(s0.clone(), &"".into()).unwrap();

ethcore/src/engines/validator_set/test.rs

@@ -93,6 +93,7 @@ impl ValidatorSet for TestSet {
 	}
 
 	fn report_benign(&self, _validator: &Address, _set_block: BlockNumber, block: BlockNumber) {
+		trace!(target: "engine", "test validator set recording benign misbehaviour");
 		self.last_benign.store(block as usize, AtomicOrdering::SeqCst)
 	}
 }