babe, grandpa: restrict info logging during initial sync (#5564)

* babe: restrict info logging during initial sync

* grandpa: restrict info logging during initial sync

* grandpa: fix test compilation

* grandpa: remove afg_log macro mod

substrate/client/consensus/babe/src/lib.rs

@@ -101,7 +101,7 @@ use sc_client_api::{
 use sp_block_builder::BlockBuilder as BlockBuilderApi;
 
 use futures::prelude::*;
-use log::{warn, debug, info, trace};
+use log::{debug, info, log, trace, warn};
 use sc_consensus_slots::{
 	SlotWorker, SlotInfo, SlotCompatible, StorageChanges, CheckedHeader, check_equivocation,
 };
@@ -222,16 +222,6 @@ fn babe_err<B: BlockT>(error: Error<B>) -> Error<B> {
 	error
 }
 
-macro_rules! babe_info {
-	($($i: expr),+) => {
-		{
-			info!(target: "babe", $($i),+);
-			format!($($i),+)
-		}
-	};
-}
-
-
 /// Intermediate value passed to block importer.
 pub struct BabeIntermediate<B: BlockT> {
 	/// The epoch descriptor.
@@ -368,7 +358,7 @@ pub fn start_babe<B, C, SC, E, I, SO, CAW, Error>(BabeParams {
 		&inherent_data_providers,
 	)?;
 
-	babe_info!("👶 Starting BABE Authorship worker");
+	info!(target: "babe", "👶 Starting BABE Authorship worker");
 	Ok(sc_consensus_slots::start_slot_worker(
 		config.0,
 		select_chain,
@@ -1010,15 +1000,29 @@ impl<Block, Client, Inner> BlockImport<Block> for BabeBlockImport<Block, Client,
 				ConsensusError::ClientImport(Error::<Block>::FetchEpoch(parent_hash).into())
 			})?;
 
-			babe_info!("👶 New epoch {} launching at block {} (block slot {} >= start slot {}).",
-					   viable_epoch.as_ref().epoch_index,
-					   hash,
-					   slot_number,
-					   viable_epoch.as_ref().start_slot);
+			// restrict info logging during initial sync to avoid spam
+			let log_level = if block.origin == BlockOrigin::NetworkInitialSync {
+				log::Level::Debug
+			} else {
+				log::Level::Info
+			};
+
+			log!(target: "babe",
+				log_level, 
+				"👶 New epoch {} launching at block {} (block slot {} >= start slot {}).",
+				viable_epoch.as_ref().epoch_index,
+				hash,
+				slot_number,
+				viable_epoch.as_ref().start_slot,
+			);
 
 			let next_epoch = viable_epoch.increment(next_epoch_descriptor);
 
-			babe_info!("👶 Next epoch starts at slot {}", next_epoch.as_ref().start_slot);
+			log!(target: "babe",
+				log_level,
+				"👶 Next epoch starts at slot {}",
+				next_epoch.as_ref().start_slot,
+			);
 
 			// prune the tree of epochs not part of the finalized chain or
 			// that are not live anymore, and then track the given epoch change

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

@@ -20,7 +20,7 @@ use fork_tree::ForkTree;
 use parking_lot::RwLock;
 use finality_grandpa::voter_set::VoterSet;
 use parity_scale_codec::{Encode, Decode};
-use log::{debug, info};
+use log::debug;
 use sc_telemetry::{telemetry, CONSENSUS_INFO};
 use sp_finality_grandpa::{AuthorityId, AuthorityList};
 
@@ -250,6 +250,7 @@ where
 		best_hash: H,
 		best_number: N,
 		is_descendent_of: &F,
+		initial_sync: bool,
 	) -> Result<Option<(N, Self)>, E>
 		where F: Fn(&H, &H) -> Result<bool, E>,
 	{
@@ -262,8 +263,10 @@ where
 			// check if the given best block is in the same branch as the block that signaled the change.
 			if is_descendent_of(&change.canon_hash, &best_hash)? {
 				// apply this change: make the set canonical
-				info!(target: "afg", "👴 Applying authority set change forced at block #{:?}",
-					  change.canon_height);
+				afg_log!(initial_sync,
+					"👴 Applying authority set change forced at block #{:?}",
+					change.canon_height,
+				);
 				telemetry!(CONSENSUS_INFO; "afg.applying_forced_authority_set_change";
 					"block" => ?change.canon_height
 				);
@@ -305,6 +308,7 @@ where
 		finalized_hash: H,
 		finalized_number: N,
 		is_descendent_of: &F,
+		initial_sync: bool,
 	) -> Result<Status<H, N>, fork_tree::Error<E>>
 		where F: Fn(&H, &H) -> Result<bool, E>,
 			  E: std::error::Error,
@@ -328,8 +332,10 @@ where
 				self.pending_forced_changes.clear();
 
 				if let Some(change) = change {
-					info!(target: "afg", "👴 Applying authority set change scheduled at block #{:?}",
-						  change.canon_height);
+					afg_log!(initial_sync,
+						"👴 Applying authority set change scheduled at block #{:?}",
+						change.canon_height,
+					);
 					telemetry!(CONSENSUS_INFO; "afg.applying_scheduled_authority_set_change";
 						"block" => ?change.canon_height
 					);
@@ -599,11 +605,16 @@ mod tests {
 		);
 
 		// finalizing "hash_c" won't enact the change signaled at "hash_a" but it will prune out "hash_b"
-		let status = authorities.apply_standard_changes("hash_c", 11, &is_descendent_of(|base, hash| match (*base, *hash) {
-			("hash_a", "hash_c") => true,
-			("hash_b", "hash_c") => false,
-			_ => unreachable!(),
-		})).unwrap();
+		let status = authorities.apply_standard_changes(
+			"hash_c",
+			11,
+			&is_descendent_of(|base, hash| match (*base, *hash) {
+				("hash_a", "hash_c") => true,
+				("hash_b", "hash_c") => false,
+				_ => unreachable!(),
+			}),
+			false,
+		).unwrap();
 
 		assert!(status.changed);
 		assert_eq!(status.new_set_block, None);
@@ -613,10 +624,15 @@ mod tests {
 		);
 
 		// finalizing "hash_d" will enact the change signaled at "hash_a"
-		let status = authorities.apply_standard_changes("hash_d", 15, &is_descendent_of(|base, hash| match (*base, *hash) {
-			("hash_a", "hash_d") => true,
-			_ => unreachable!(),
-		})).unwrap();
+		let status = authorities.apply_standard_changes(
+			"hash_d",
+			15,
+			&is_descendent_of(|base, hash| match (*base, *hash) {
+				("hash_a", "hash_d") => true,
+				_ => unreachable!(),
+			}),
+			false,
+		).unwrap();
 
 		assert!(status.changed);
 		assert_eq!(status.new_set_block, Some(("hash_d", 15)));
@@ -671,12 +687,18 @@ mod tests {
 		});
 
 		// trying to finalize past `change_c` without finalizing `change_a` first
-		match authorities.apply_standard_changes("hash_d", 40, &is_descendent_of) {
-			Err(fork_tree::Error::UnfinalizedAncestor) => {},
-			_ => unreachable!(),
-		}
+		assert!(matches!(
+			authorities.apply_standard_changes("hash_d", 40, &is_descendent_of, false),
+			Err(fork_tree::Error::UnfinalizedAncestor)
+		));
+
+		let status = authorities.apply_standard_changes(
+			"hash_b",
+			15,
+			&is_descendent_of,
+			false,
+		).unwrap();
 
-		let status = authorities.apply_standard_changes("hash_b", 15, &is_descendent_of).unwrap();
 		assert!(status.changed);
 		assert_eq!(status.new_set_block, Some(("hash_b", 15)));
 
@@ -684,7 +706,13 @@ mod tests {
 		assert_eq!(authorities.set_id, 1);
 
 		// after finalizing `change_a` it should be possible to finalize `change_c`
-		let status = authorities.apply_standard_changes("hash_d", 40, &is_descendent_of).unwrap();
+		let status = authorities.apply_standard_changes(
+			"hash_d",
+			40,
+			&is_descendent_of,
+			false,
+		).unwrap();
+
 		assert!(status.changed);
 		assert_eq!(status.new_set_block, Some(("hash_d", 40)));
 
@@ -817,20 +845,30 @@ mod tests {
 		assert!(authorities.add_pending_change(change_c, &is_descendent_of_a).is_err());
 
 		// too early.
-		assert!(authorities.apply_forced_changes("hash_a10", 10, &static_is_descendent_of(true)).unwrap().is_none());
+		assert!(
+			authorities.apply_forced_changes("hash_a10", 10, &static_is_descendent_of(true), false)
+				.unwrap()
+				.is_none()
+		);
 
 		// too late.
-		assert!(authorities.apply_forced_changes("hash_a16", 16, &static_is_descendent_of(true)).unwrap().is_none());
+		assert!(
+			authorities.apply_forced_changes("hash_a16", 16, &static_is_descendent_of(true), false)
+				.unwrap()
+				.is_none()
+		);
 
 		// on time -- chooses the right change.
 		assert_eq!(
-			authorities.apply_forced_changes("hash_a15", 15, &is_descendent_of_a).unwrap().unwrap(),
+			authorities.apply_forced_changes("hash_a15", 15, &is_descendent_of_a, false)
+				.unwrap()
+				.unwrap(),
 			(42, AuthoritySet {
 				current_authorities: set_a,
 				set_id: 1,
 				pending_standard_changes: ForkTree::new(),
 				pending_forced_changes: Vec::new(),
-			})
+			}),
 		);
 	}
 }

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

@@ -20,7 +20,7 @@ use std::pin::Pin;
 use std::sync::Arc;
 use std::time::Duration;
 
-use log::{debug, warn, info};
+use log::{debug, warn};
 use parity_scale_codec::{Decode, Encode};
 use futures::prelude::*;
 use futures_timer::Delay;
@@ -911,6 +911,7 @@ where
 			hash,
 			number,
 			(round, commit).into(),
+			false,
 		)
 	}
 
@@ -970,6 +971,7 @@ pub(crate) fn finalize_block<BE, Block, Client>(
 	hash: Block::Hash,
 	number: NumberFor<Block>,
 	justification_or_commit: JustificationOrCommit<Block>,
+	initial_sync: bool,
 ) -> Result<(), CommandOrError<Block::Hash, NumberFor<Block>>> where
 	Block:  BlockT,
 	BE: Backend<Block>,
@@ -1011,6 +1013,7 @@ pub(crate) fn finalize_block<BE, Block, Client>(
 			hash,
 			number,
 			&is_descendent_of::<Block, _>(&*client, None),
+			initial_sync,
 		).map_err(|e| Error::Safety(e.to_string()))?;
 
 		// check if this is this is the first finalization of some consensus changes
@@ -1091,9 +1094,15 @@ pub(crate) fn finalize_block<BE, Block, Client>(
 			let (new_id, set_ref) = authority_set.current();
 
 			if set_ref.len() > 16 {
-				info!("👴 Applying GRANDPA set change to new set with {} authorities", set_ref.len());
+				afg_log!(initial_sync,
+					"👴 Applying GRANDPA set change to new set with {} authorities",
+					set_ref.len(),
+				);
 			} else {
-				info!("👴 Applying GRANDPA set change to new set {:?}", set_ref);
+				afg_log!(initial_sync,
+					"👴 Applying GRANDPA set change to new set {:?}",
+					set_ref,
+				);
 			}
 
 			telemetry!(CONSENSUS_INFO; "afg.generating_new_authority_set";

substrate/client/finality-grandpa/src/import.rs

@@ -16,7 +16,7 @@
 
 use std::{sync::Arc, collections::HashMap};
 
-use log::{debug, trace, info};
+use log::{debug, trace};
 use parity_scale_codec::Encode;
 use parking_lot::RwLockWriteGuard;
 
@@ -27,7 +27,7 @@ use sp_api::{TransactionFor};
 
 use sp_consensus::{
 	BlockImport, Error as ConsensusError,
-	BlockCheckParams, BlockImportParams, ImportResult, JustificationImport,
+	BlockCheckParams, BlockImportParams, BlockOrigin, ImportResult, JustificationImport,
 	SelectChain,
 };
 use sp_finality_grandpa::{ConsensusLog, ScheduledChange, SetId, GRANDPA_ENGINE_ID};
@@ -128,7 +128,12 @@ impl<BE, Block: BlockT, Client, SC> JustificationImport<Block>
 		number: NumberFor<Block>,
 		justification: Justification,
 	) -> Result<(), Self::Error> {
-		GrandpaBlockImport::import_justification(self, hash, number, justification, false)
+		// this justification was requested by the sync service, therefore we
+		// are not sure if it should enact a change or not. it could have been a
+		// request made as part of initial sync but that means the justification
+		// wasn't part of the block and was requested asynchronously, probably
+		// makes sense to log in that case.
+		GrandpaBlockImport::import_justification(self, hash, number, justification, false, false)
 	}
 }
 
@@ -250,6 +255,7 @@ where
 		&self,
 		block: &mut BlockImportParams<Block, TransactionFor<Client, Block>>,
 		hash: Block::Hash,
+		initial_sync: bool,
 	) -> Result<PendingSetChanges<Block>, ConsensusError> {
 		// when we update the authorities, we need to hold the lock
 		// until the block is written to prevent a race if we need to restore
@@ -324,7 +330,9 @@ where
 		}
 
 		let applied_changes = {
-			let forced_change_set = guard.as_mut().apply_forced_changes(hash, number, &is_descendent_of)
+			let forced_change_set = guard
+				.as_mut()
+				.apply_forced_changes(hash, number, &is_descendent_of, initial_sync)
 				.map_err(|e| ConsensusError::ClientImport(e.to_string()))
 				.map_err(ConsensusError::from)?;
 
@@ -419,7 +427,10 @@ impl<BE, Block: BlockT, Client, SC> BlockImport<Block>
 			Err(e) => return Err(ConsensusError::ClientImport(e.to_string()).into()),
 		}
 
-		let pending_changes = self.make_authorities_changes(&mut block, hash)?;
+		// on initial sync we will restrict logging under info to avoid spam.
+		let initial_sync = block.origin == BlockOrigin::NetworkInitialSync;
+
+		let pending_changes = self.make_authorities_changes(&mut block, hash, initial_sync)?;
 
 		// we don't want to finalize on `inner.import_block`
 		let mut justification = block.justification.take();
@@ -492,7 +503,15 @@ impl<BE, Block: BlockT, Client, SC> BlockImport<Block>
 
 		match justification {
 			Some(justification) => {
-				self.import_justification(hash, number, justification, needs_justification).unwrap_or_else(|err| {
+				let import_res = self.import_justification(
+					hash,
+					number,
+					justification,
+					needs_justification,
+					initial_sync,
+				);
+
+				import_res.unwrap_or_else(|err| {
 					if needs_justification || enacts_consensus_change {
 						debug!(target: "afg", "Imported block #{} that enacts authority set change with \
 							invalid justification: {:?}, requesting justification from peers.", number, err);
@@ -604,6 +623,7 @@ where
 		number: NumberFor<Block>,
 		justification: Justification,
 		enacts_change: bool,
+		initial_sync: bool,
 	) -> Result<(), ConsensusError> {
 		let justification = GrandpaJustification::decode_and_verify_finalizes(
 			&justification,
@@ -625,12 +645,17 @@ where
 			hash,
 			number,
 			justification.into(),
+			initial_sync,
 		);
 
 		match result {
 			Err(CommandOrError::VoterCommand(command)) => {
-				info!(target: "afg", "👴 Imported justification for block #{} that triggers \
-					command {}, signaling voter.", number, command);
+				afg_log!(initial_sync,
+					"👴 Imported justification for block #{} that triggers \
+					command {}, signaling voter.",
+					number,
+					command,
+				);
 
 				// send the command to the voter
 				let _ = self.send_voter_commands.unbounded_send(command);

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

@@ -84,6 +84,23 @@ use std::time::Duration;
 use std::pin::Pin;
 use std::task::{Poll, Context};
 
+// utility logging macro that takes as first argument a conditional to
+// decide whether to log under debug or info level (useful to restrict
+// logging under initial sync).
+macro_rules! afg_log {
+	($condition:expr, $($msg: expr),+ $(,)?) => {
+		{
+			let log_level = if $condition {
+				log::Level::Debug
+			} else {
+				log::Level::Info
+			};
+
+			log::log!(target: "afg", log_level, $($msg),+);
+		}
+	};
+}
+
 mod authorities;
 mod aux_schema;
 mod communication;

substrate/client/finality-grandpa/src/observer.rs

@@ -124,6 +124,7 @@ fn grandpa_observer<BE, Block: BlockT, Client, S, F>(
 				finalized_hash,
 				finalized_number,
 				(round, commit).into(),
+				false,
 			) {
 				Ok(_) => {},
 				Err(e) => return future::err(e),