From 1a9c0fee307b64780bac775896ab9b16c76f4018 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Andr=C3=A9=20Silva?= <123550+andresilva@users.noreply.github.com> Date: Tue, 7 Apr 2020 21:11:22 +0100 Subject: [PATCH] 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 | 40 +++++---- .../finality-grandpa/src/authorities.rs | 86 +++++++++++++------ .../finality-grandpa/src/environment.rs | 15 +++- .../client/finality-grandpa/src/import.rs | 41 +++++++-- substrate/client/finality-grandpa/src/lib.rs | 17 ++++ .../client/finality-grandpa/src/observer.rs | 1 + 6 files changed, 147 insertions(+), 53 deletions(-) diff --git a/substrate/client/consensus/babe/src/lib.rs b/substrate/client/consensus/babe/src/lib.rs index 5365aae2aa..092bf8153b 100644 --- a/substrate/client/consensus/babe/src/lib.rs +++ b/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(error: Error) -> Error { error } -macro_rules! babe_info { - ($($i: expr),+) => { - { - info!(target: "babe", $($i),+); - format!($($i),+) - } - }; -} - - /// Intermediate value passed to block importer. pub struct BabeIntermediate { /// The epoch descriptor. @@ -368,7 +358,7 @@ pub fn start_babe(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 BlockImport for BabeBlockImport::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 diff --git a/substrate/client/finality-grandpa/src/authorities.rs b/substrate/client/finality-grandpa/src/authorities.rs index 4709216ebe..fe3f2dd19e 100644 --- a/substrate/client/finality-grandpa/src/authorities.rs +++ b/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, E> where F: Fn(&H, &H) -> Result, { @@ -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, fork_tree::Error> where F: Fn(&H, &H) -> Result, 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(), - }) + }), ); } } diff --git a/substrate/client/finality-grandpa/src/environment.rs b/substrate/client/finality-grandpa/src/environment.rs index dec9492482..d3bbc1adb3 100644 --- a/substrate/client/finality-grandpa/src/environment.rs +++ b/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( hash: Block::Hash, number: NumberFor, justification_or_commit: JustificationOrCommit, + initial_sync: bool, ) -> Result<(), CommandOrError>> where Block: BlockT, BE: Backend, @@ -1011,6 +1013,7 @@ pub(crate) fn finalize_block( hash, number, &is_descendent_of::(&*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( 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"; diff --git a/substrate/client/finality-grandpa/src/import.rs b/substrate/client/finality-grandpa/src/import.rs index faf3193641..c1e32dfa6c 100644 --- a/substrate/client/finality-grandpa/src/import.rs +++ b/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 JustificationImport number: NumberFor, 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>, hash: Block::Hash, + initial_sync: bool, ) -> Result, 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 BlockImport 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 BlockImport 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, 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); diff --git a/substrate/client/finality-grandpa/src/lib.rs b/substrate/client/finality-grandpa/src/lib.rs index 800fe3442e..6fab89ac68 100644 --- a/substrate/client/finality-grandpa/src/lib.rs +++ b/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; diff --git a/substrate/client/finality-grandpa/src/observer.rs b/substrate/client/finality-grandpa/src/observer.rs index fbe19a0716..1e6c8ddf18 100644 --- a/substrate/client/finality-grandpa/src/observer.rs +++ b/substrate/client/finality-grandpa/src/observer.rs @@ -124,6 +124,7 @@ fn grandpa_observer( finalized_hash, finalized_number, (round, commit).into(), + false, ) { Ok(_) => {}, Err(e) => return future::err(e),