Add grandpa telemetry (+ other minor improvements) (#1997)

* Support skipping the interactive purge prompt

Skip it via `cargo run -- purge-chain -y`.

* Fix typos

* Add Grandpa telemetry

* Address comments

* Revert unnecessary version bump

* Version bump to make CI run

* Remove unnecessary cast

* Do not bump version

substrate/core/finality-grandpa/src/authorities.rs

@@ -22,6 +22,7 @@ use substrate_primitives::ed25519;
 use grandpa::VoterSet;
 use parity_codec::{Encode, Decode};
 use log::{debug, info};
+use substrate_telemetry::{telemetry, CONSENSUS_INFO};
 
 use std::cmp::Ord;
 use std::fmt::Debug;
@@ -261,6 +262,9 @@ where
 				// apply this change: make the set canonical
 				info!(target: "finality", "Applying authority set change forced at block #{:?}",
 					  change.canon_height);
+				telemetry!(CONSENSUS_INFO; "afg.applying_forced_authority_set_change";
+					"block" => ?change.canon_height
+				);
 
 				let median_last_finalized = match change.delay_kind {
 					DelayKind::Best { ref median_last_finalized } => median_last_finalized.clone(),
@@ -324,6 +328,9 @@ where
 				if let Some(change) = change {
 					info!(target: "finality", "Applying authority set change scheduled at block #{:?}",
 						  change.canon_height);
+					telemetry!(CONSENSUS_INFO; "afg.applying_scheduled_authority_set_change";
+						"block" => ?change.canon_height
+					);
 
 					self.current_authorities = change.next_authorities;
 					self.set_id += 1;

substrate/core/finality-grandpa/src/communication.rs

@@ -21,11 +21,13 @@ use std::collections::HashMap;
 use std::sync::Arc;
 
 use grandpa::VoterSet;
+use grandpa::Message::{Prevote, Precommit};
 use futures::prelude::*;
 use futures::sync::mpsc;
 use log::{debug, trace};
 use parity_codec::{Encode, Decode};
 use substrate_primitives::{ed25519, Pair};
+use substrate_telemetry::{telemetry, CONSENSUS_INFO};
 use runtime_primitives::traits::Block as BlockT;
 use tokio::timer::Interval;
 use crate::{Error, Network, Message, SignedMessage, Commit,
@@ -283,6 +285,24 @@ pub(crate) fn checked_message_stream<Block: BlockT, S>(
 						debug!(target: "afg", "Skipping message from unknown voter {}", msg.message.id);
 						return Ok(None);
 					}
+
+					match &msg.message.message {
+						Prevote(prevote) => {
+							telemetry!(CONSENSUS_INFO; "afg.received_prevote";
+								"voter" => ?format!("{}", msg.message.id),
+								"target_number" => ?prevote.target_number,
+								"target_hash" => ?prevote.target_hash,
+							);
+						},
+						Precommit(precommit) => {
+							telemetry!(CONSENSUS_INFO; "afg.received_precommit";
+								"voter" => ?format!("{}", msg.message.id),
+								"target_number" => ?precommit.target_number,
+								"target_hash" => ?precommit.target_hash,
+							);
+						},
+					};
+
 					Ok(Some(msg.message))
 				}
 				_ => {
@@ -436,6 +456,15 @@ pub(crate) fn checked_commit_stream<Block: BlockT, S>(
 			match msg {
 				GossipMessage::Commit(msg) => {
 					let round = msg.round;
+					let precommits_signed_by: Vec<String> =
+						msg.message.auth_data.iter().map(move |(_, a)| {
+							format!("{}", a)
+						}).collect();
+					telemetry!(CONSENSUS_INFO; "afg.received_commit";
+						"contains_precommits_signed_by" => ?precommits_signed_by,
+						"target_number" => ?msg.message.target_number,
+						"target_hash" => ?msg.message.target_hash,
+					);
 					check_compact_commit::<Block>(msg.message, &*voters).map(move |c| (round, c))
 				},
 				_ => {
@@ -477,6 +506,9 @@ impl<Block: BlockT, N: Network<Block>> Sink for CommitsOut<Block, N> {
 		}
 
 		let (round, commit) = input;
+		telemetry!(CONSENSUS_INFO; "afg.commit_issued";
+			"target_number" => ?commit.target_number, "target_hash" => ?commit.target_hash,
+		);
 		let (precommits, auth_data) = commit.precommits.into_iter()
 			.map(|signed| (signed.precommit, (signed.signature, signed.id)))
 			.unzip();

substrate/core/finality-grandpa/src/environment.rs

@@ -34,6 +34,7 @@ use runtime_primitives::traits::{
 	As, Block as BlockT, Header as HeaderT, NumberFor, One, Zero,
 };
 use substrate_primitives::{Blake2Hasher, ed25519, H256, Pair};
+use substrate_telemetry::{telemetry, CONSENSUS_INFO};
 
 use crate::{
 	Commit, Config, Error, Network, Precommit, Prevote,
@@ -469,6 +470,9 @@ pub(crate) fn finalize_block<B, Block: BlockT<Hash=H256>, E, RA>(
 			warn!(target: "finality", "Error applying finality to block {:?}: {:?}", (hash, number), e);
 			e
 		})?;
+		telemetry!(CONSENSUS_INFO; "afg.finalized_blocks_up_to";
+			"number" => ?number, "hash" => ?hash,
+		);
 
 		let new_authorities = if let Some((canon_hash, canon_number)) = status.new_set_block {
 			// the authority set has changed.
@@ -480,6 +484,11 @@ pub(crate) fn finalize_block<B, Block: BlockT<Hash=H256>, E, RA>(
 				info!("Applying GRANDPA set change to new set {:?}", set_ref);
 			}
 
+			telemetry!(CONSENSUS_INFO; "afg.generating_new_authority_set";
+				"number" => ?canon_number, "hash" => ?canon_hash,
+				"authorities" => ?set_ref.to_vec(),
+				"set_id" => ?new_id,
+			);
 			Some(NewAuthoritySet {
 				canon_hash,
 				canon_number,

substrate/core/finality-grandpa/src/finality_proof.rs

@@ -44,6 +44,7 @@ use runtime_primitives::traits::{
 };
 use substrate_primitives::{ed25519, H256};
 use ed25519::Public as AuthorityId;
+use substrate_telemetry::{telemetry, CONSENSUS_INFO};
 
 use crate::justification::GrandpaJustification;
 
@@ -170,14 +171,14 @@ fn do_check_finality_proof<Block: BlockT<Hash=H256>, C, J>(
 		}
 	}
 
-	// check that the last header in finalization path is the jsutification target block
+	// check that the last header in finalization path is the justification target block
 	let just_block = proof.justification.target_block();
 	{
 		let finalized_header = proof.finalization_path.last()
 			.expect("checked above that proof.finalization_path is not empty; qed");
 		if *finalized_header.number() != just_block.0 || finalized_header.hash() != just_block.1 {
 			return Err(ClientErrorKind::BadJustification(
-				"finality proof: target jsutification block is not a part of finalized path".into()
+				"finality proof: target justification block is not a part of finalized path".into()
 			).into());
 		}
 	}
@@ -196,6 +197,8 @@ fn do_check_finality_proof<Block: BlockT<Hash=H256>, C, J>(
 	// and now check justification
 	proof.justification.verify(set_id, &grandpa_authorities.into_iter().collect())?;
 
+	telemetry!(CONSENSUS_INFO; "afg.finality_proof_ok";
+		"set_id" => ?set_id, "finalized_header_hash" => ?block.1);
 	Ok(proof.finalization_path)
 }
 

substrate/core/finality-grandpa/src/lib.rs

@@ -69,7 +69,7 @@ use fg_primitives::GrandpaApi;
 use inherents::InherentDataProviders;
 use runtime_primitives::generic::BlockId;
 use substrate_primitives::{ed25519, H256, Blake2Hasher, Pair};
-use substrate_telemetry::{telemetry, CONSENSUS_TRACE, CONSENSUS_DEBUG, CONSENSUS_WARN};
+use substrate_telemetry::{telemetry, CONSENSUS_TRACE, CONSENSUS_DEBUG, CONSENSUS_WARN, CONSENSUS_INFO};
 
 use srml_finality_tracker;
 
@@ -388,6 +388,17 @@ impl<Block: BlockT> GossipValidator<Block> {
 		}
 
 		let topic = commit_topic::<Block>(full.set_id);
+
+		let precommits_signed_by: Vec<String> = full.message.auth_data.iter().map(move |(_, a)| {
+			format!("{}", a)
+		}).collect();
+		telemetry!(CONSENSUS_INFO; "afg.received_commit_msg";
+			"contains_precommits_signed_by" => ?precommits_signed_by,
+			"round" => ?full.round,
+			"set_id" => ?full.set_id,
+			"topic" => ?topic,
+			"block_hash" => ?full.message,
+		);
 		network_gossip::ValidationResult::Valid(topic)
 	}
 }
@@ -750,7 +761,13 @@ fn register_finality_tracker_inherent_data_provider<B, E, Block: BlockT<Hash=H25
 			.register_provider(srml_finality_tracker::InherentDataProvider::new(move || {
 				match client.backend().blockchain().info() {
 					Err(e) => Err(std::borrow::Cow::Owned(e.to_string())),
-					Ok(info) => Ok(info.finalized_number),
+					Ok(info) => {
+						telemetry!(CONSENSUS_INFO; "afg.finalized";
+							"finalized_number" => ?info.finalized_number,
+							"finalized_hash" => ?info.finalized_hash,
+						);
+						Ok(info.finalized_number)
+					},
 				}
 			}))
 			.map_err(|err| consensus_common::ErrorKind::InherentData(err.into()).into())
@@ -862,6 +879,16 @@ pub fn run_grandpa<B, E, Block: BlockT<Hash=H256>, N, RA>(
 		let handle_voter_command = move |command: VoterCommand<_, _>, voter_commands_rx| {
 			match command {
 				VoterCommand::ChangeAuthorities(new) => {
+					let voters: Vec<String> = new.authorities.iter().map(move |(a, _)| {
+						format!("{}", a)
+					}).collect();
+					telemetry!(CONSENSUS_INFO; "afg.voter_command_change_authorities";
+						"number" => ?new.canon_number,
+						"hash" => ?new.canon_hash,
+						"voters" => ?voters,
+						"set_id" => ?new.set_id,
+					);
+
 					// start the new authority set using the block where the
 					// set changed (not where the signal happened!) as the base.
 					let genesis_state = RoundState::genesis((new.canon_hash, new.canon_number));