From febaa3db8977c7629c079d74522088ceafeed315 Mon Sep 17 00:00:00 2001 From: Davide Galassi Date: Thu, 8 Dec 2022 16:28:15 +0100 Subject: [PATCH 1/3] Use shared LOG_TARGET in consensus related crates --- client/consensus/aura/src/import_queue.rs | 7 +- client/consensus/aura/src/lib.rs | 8 +- client/consensus/babe/src/aux_schema.rs | 4 +- client/consensus/babe/src/lib.rs | 92 ++++++++++--------- client/consensus/babe/src/tests.rs | 10 +- client/consensus/babe/src/verification.rs | 15 +-- client/consensus/common/src/import_queue.rs | 37 +++++--- .../common/src/import_queue/basic_queue.rs | 24 +++-- .../manual-seal/src/consensus/babe.rs | 6 +- client/consensus/manual-seal/src/lib.rs | 2 + client/consensus/pow/src/lib.rs | 20 ++-- client/consensus/pow/src/worker.rs | 34 ++----- client/consensus/slots/src/lib.rs | 14 +-- client/consensus/slots/src/slots.rs | 6 +- client/finality-grandpa/src/authorities.rs | 20 ++-- client/finality-grandpa/src/aux_schema.rs | 13 ++- .../src/communication/gossip.rs | 47 ++++++---- .../finality-grandpa/src/communication/mod.rs | 39 +++++--- .../src/communication/periodic.rs | 8 +- client/finality-grandpa/src/environment.rs | 80 +++++++++++----- client/finality-grandpa/src/finality_proof.rs | 10 +- client/finality-grandpa/src/import.rs | 17 ++-- client/finality-grandpa/src/lib.rs | 25 +++-- client/finality-grandpa/src/observer.rs | 6 +- client/finality-grandpa/src/until_imported.rs | 6 +- frame/aura/src/lib.rs | 4 +- frame/babe/src/equivocation.rs | 16 +--- frame/babe/src/lib.rs | 2 + frame/grandpa/src/equivocation.rs | 16 +--- frame/grandpa/src/lib.rs | 2 + frame/grandpa/src/migrations/v4.rs | 4 +- 31 files changed, 344 insertions(+), 250 deletions(-) diff --git a/client/consensus/aura/src/import_queue.rs b/client/consensus/aura/src/import_queue.rs index b17feae45897e..e304b1b8949ba 100644 --- a/client/consensus/aura/src/import_queue.rs +++ b/client/consensus/aura/src/import_queue.rs @@ -20,6 +20,7 @@ use crate::{ aura_err, authorities, find_pre_digest, slot_author, AuthorityId, CompatibilityMode, Error, + LOG_TARGET, }; use codec::{Codec, Decode, Encode}; use log::{debug, info, trace}; @@ -88,7 +89,7 @@ where .map_err(Error::Client)? { info!( - target: "aura", + target: LOG_TARGET, "Slot author is equivocating at slot {} with headers {:?} and {:?}", slot, equivocation_proof.first_header.hash(), @@ -255,7 +256,7 @@ where block.body = Some(inner_body); } - trace!(target: "aura", "Checked {:?}; importing.", pre_header); + trace!(target: LOG_TARGET, "Checked {:?}; importing.", pre_header); telemetry!( self.telemetry; CONSENSUS_TRACE; @@ -271,7 +272,7 @@ where Ok((block, None)) }, CheckedHeader::Deferred(a, b) => { - debug!(target: "aura", "Checking {:?} failed; {:?}, {:?}.", hash, a, b); + debug!(target: LOG_TARGET, "Checking {:?} failed; {:?}, {:?}.", hash, a, b); telemetry!( self.telemetry; CONSENSUS_DEBUG; diff --git a/client/consensus/aura/src/lib.rs b/client/consensus/aura/src/lib.rs index 50a02726cf56a..76217c35df905 100644 --- a/client/consensus/aura/src/lib.rs +++ b/client/consensus/aura/src/lib.rs @@ -72,6 +72,8 @@ pub use sp_consensus_aura::{ AuraApi, ConsensusLog, SlotDuration, AURA_ENGINE_ID, }; +const LOG_TARGET: &str = "aura"; + type AuthorityId

=

::Public; /// Run `AURA` in a compatibility mode. @@ -530,7 +532,7 @@ where } fn aura_err(error: Error) -> Error { - debug!(target: "aura", "{}", error); + debug!(target: LOG_TARGET, "{}", error); error } @@ -580,10 +582,10 @@ pub fn find_pre_digest(header: &B::Header) -> Resul let mut pre_digest: Option = None; for log in header.digest().logs() { - trace!(target: "aura", "Checking log {:?}", log); + trace!(target: LOG_TARGET, "Checking log {:?}", log); match (CompatibleDigestItem::::as_aura_pre_digest(log), pre_digest.is_some()) { (Some(_), true) => return Err(aura_err(Error::MultipleHeaders)), - (None, _) => trace!(target: "aura", "Ignoring digest not meant for us"), + (None, _) => trace!(target: LOG_TARGET, "Ignoring digest not meant for us"), (s, false) => pre_digest = s, } } diff --git a/client/consensus/babe/src/aux_schema.rs b/client/consensus/babe/src/aux_schema.rs index fef84bda86974..2a09aa738f4ec 100644 --- a/client/consensus/babe/src/aux_schema.rs +++ b/client/consensus/babe/src/aux_schema.rs @@ -21,7 +21,7 @@ use codec::{Decode, Encode}; use log::info; -use crate::{migration::EpochV0, Epoch}; +use crate::{migration::EpochV0, Epoch, LOG_TARGET}; use sc_client_api::backend::AuxStore; use sc_consensus_epochs::{ migration::{EpochChangesV0For, EpochChangesV1For}, @@ -82,7 +82,7 @@ pub fn load_epoch_changes( let epoch_changes = SharedEpochChanges::::new(maybe_epoch_changes.unwrap_or_else(|| { info!( - target: "babe", + target: LOG_TARGET, "👶 Creating empty BABE epoch changes on what appears to be first startup.", ); EpochChangesFor::::default() diff --git a/client/consensus/babe/src/lib.rs b/client/consensus/babe/src/lib.rs index 109e5aade02a7..7891443151cca 100644 --- a/client/consensus/babe/src/lib.rs +++ b/client/consensus/babe/src/lib.rs @@ -148,6 +148,8 @@ pub mod aux_schema; #[cfg(test)] mod tests; +const LOG_TARGET: &str = "babe"; + /// BABE epoch information #[derive(Decode, Encode, PartialEq, Eq, Clone, Debug)] pub struct Epoch { @@ -322,7 +324,7 @@ impl From> for String { } fn babe_err(error: Error) -> Error { - debug!(target: "babe", "{}", error); + debug!(target: LOG_TARGET, "{}", error); error } @@ -344,7 +346,7 @@ where let block_id = if client.usage_info().chain.finalized_state.is_some() { BlockId::Hash(client.usage_info().chain.best_hash) } else { - debug!(target: "babe", "No finalized state is available. Reading config from genesis"); + debug!(target: LOG_TARGET, "No finalized state is available. Reading config from genesis"); BlockId::Hash(client.usage_info().chain.genesis_hash) }; @@ -485,7 +487,7 @@ where telemetry, }; - info!(target: "babe", "👶 Starting BABE Authorship worker"); + info!(target: LOG_TARGET, "👶 Starting BABE Authorship worker"); let slot_worker = sc_consensus_slots::start_slot_worker( babe_link.config.slot_duration(), @@ -522,12 +524,8 @@ fn aux_storage_cleanup + HeaderBackend, Block: B Ok(meta) => { aux_keys.insert(aux_schema::block_weight_key(meta.parent)); }, - Err(err) => warn!( - target: "babe", - "Failed to lookup metadata for block `{:?}`: {}", - first, - err, - ), + Err(err) => + warn!(target: LOG_TARGET, "Failed to lookup metadata for block `{:?}`: {}", first, err,), } // Cleans data for finalized block's ancestors @@ -566,10 +564,8 @@ fn aux_storage_cleanup + HeaderBackend, Block: B }, Err(err) => { warn!( - target: "babe", - "Header lookup fail while cleaning data for block {:?}: {}", - hash, - err, + target: LOG_TARGET, + "Header lookup fail while cleaning data for block {:?}: {}", hash, err, ); break }, @@ -739,7 +735,7 @@ where type AuxData = ViableEpochDescriptor, Epoch>; fn logging_target(&self) -> &'static str { - "babe" + LOG_TARGET } fn block_import(&mut self) -> &mut Self::BlockImport { @@ -772,7 +768,7 @@ where slot: Slot, epoch_descriptor: &ViableEpochDescriptor, Epoch>, ) -> Option { - debug!(target: "babe", "Attempting to claim slot {}", slot); + debug!(target: LOG_TARGET, "Attempting to claim slot {}", slot); let s = authorship::claim_slot( slot, self.epoch_changes @@ -783,7 +779,7 @@ where ); if s.is_some() { - debug!(target: "babe", "Claimed slot {}", slot); + debug!(target: LOG_TARGET, "Claimed slot {}", slot); } s @@ -800,7 +796,7 @@ where Ok(()) => true, Err(e) => if e.is_full() { - warn!(target: "babe", "Trying to notify a slot but the channel is full"); + warn!(target: LOG_TARGET, "Trying to notify a slot but the channel is full"); true } else { false @@ -927,10 +923,10 @@ pub fn find_pre_digest(header: &B::Header) -> Result = None; for log in header.digest().logs() { - trace!(target: "babe", "Checking log {:?}, looking for pre runtime digest", log); + trace!(target: LOG_TARGET, "Checking log {:?}, looking for pre runtime digest", log); match (log.as_babe_pre_digest(), pre_digest.is_some()) { (Some(_), true) => return Err(babe_err(Error::MultiplePreRuntimeDigests)), - (None, _) => trace!(target: "babe", "Ignoring digest not meant for us"), + (None, _) => trace!(target: LOG_TARGET, "Ignoring digest not meant for us"), (s, false) => pre_digest = s, } } @@ -943,13 +939,13 @@ fn find_next_epoch_digest( ) -> Result, Error> { let mut epoch_digest: Option<_> = None; for log in header.digest().logs() { - trace!(target: "babe", "Checking log {:?}, looking for epoch change digest.", log); + trace!(target: LOG_TARGET, "Checking log {:?}, looking for epoch change digest.", log); let log = log.try_to::(OpaqueDigestItemId::Consensus(&BABE_ENGINE_ID)); match (log, epoch_digest.is_some()) { (Some(ConsensusLog::NextEpochData(_)), true) => return Err(babe_err(Error::MultipleEpochChangeDigests)), (Some(ConsensusLog::NextEpochData(epoch)), false) => epoch_digest = Some(epoch), - _ => trace!(target: "babe", "Ignoring digest not meant for us"), + _ => trace!(target: LOG_TARGET, "Ignoring digest not meant for us"), } } @@ -962,13 +958,13 @@ fn find_next_config_digest( ) -> Result, Error> { let mut config_digest: Option<_> = None; for log in header.digest().logs() { - trace!(target: "babe", "Checking log {:?}, looking for epoch change digest.", log); + trace!(target: LOG_TARGET, "Checking log {:?}, looking for epoch change digest.", log); let log = log.try_to::(OpaqueDigestItemId::Consensus(&BABE_ENGINE_ID)); match (log, config_digest.is_some()) { (Some(ConsensusLog::NextConfigData(_)), true) => return Err(babe_err(Error::MultipleConfigChangeDigests)), (Some(ConsensusLog::NextConfigData(config)), false) => config_digest = Some(config), - _ => trace!(target: "babe", "Ignoring digest not meant for us"), + _ => trace!(target: LOG_TARGET, "Ignoring digest not meant for us"), } } @@ -1098,7 +1094,10 @@ where None => match generate_key_owner_proof(&best_id)? { Some(proof) => proof, None => { - debug!(target: "babe", "Equivocation offender is not part of the authority set."); + debug!( + target: LOG_TARGET, + "Equivocation offender is not part of the authority set." + ); return Ok(()) }, }, @@ -1114,7 +1113,7 @@ where ) .map_err(Error::RuntimeApi)?; - info!(target: "babe", "Submitted equivocation report for author {:?}", author); + info!(target: LOG_TARGET, "Submitted equivocation report for author {:?}", author); Ok(()) } @@ -1144,7 +1143,7 @@ where mut block: BlockImportParams, ) -> BlockVerificationResult { trace!( - target: "babe", + target: LOG_TARGET, "Verifying origin: {:?} header: {:?} justification(s): {:?} body: {:?}", block.origin, block.header, @@ -1163,7 +1162,11 @@ where return Ok((block, Default::default())) } - debug!(target: "babe", "We have {:?} logs in this header", block.header.digest().logs().len()); + debug!( + target: LOG_TARGET, + "We have {:?} logs in this header", + block.header.digest().logs().len() + ); let create_inherent_data_providers = self .create_inherent_data_providers @@ -1227,7 +1230,10 @@ where ) .await { - warn!(target: "babe", "Error checking/reporting BABE equivocation: {}", err); + warn!( + target: LOG_TARGET, + "Error checking/reporting BABE equivocation: {}", err + ); } if let Some(inner_body) = block.body { @@ -1255,7 +1261,7 @@ where block.body = Some(inner_body); } - trace!(target: "babe", "Checked {:?}; importing.", pre_header); + trace!(target: LOG_TARGET, "Checked {:?}; importing.", pre_header); telemetry!( self.telemetry; CONSENSUS_TRACE; @@ -1274,7 +1280,7 @@ where Ok((block, Default::default())) }, CheckedHeader::Deferred(a, b) => { - debug!(target: "babe", "Checking {:?} failed; {:?}, {:?}.", hash, a, b); + debug!(target: LOG_TARGET, "Checking {:?} failed; {:?}, {:?}.", hash, a, b); telemetry!( self.telemetry; CONSENSUS_DEBUG; @@ -1542,21 +1548,23 @@ where 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, - viable_epoch.as_ref().start_slot, + log!( + target: LOG_TARGET, + log_level, + "👶 New epoch {} launching at block {} (block slot {} >= start slot {}).", + viable_epoch.as_ref().epoch_index, + hash, + slot, + viable_epoch.as_ref().start_slot, ); let next_epoch = viable_epoch.increment((next_epoch_descriptor, epoch_config)); - log!(target: "babe", - log_level, - "👶 Next epoch starts at slot {}", - next_epoch.as_ref().start_slot, + log!( + target: LOG_TARGET, + 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 @@ -1587,7 +1595,7 @@ where }; if let Err(e) = prune_and_import() { - debug!(target: "babe", "Failed to launch next epoch: {}", e); + debug!(target: LOG_TARGET, "Failed to launch next epoch: {}", e); *epoch_changes = old_epoch_changes.expect("set `Some` above and not taken; qed"); return Err(e) diff --git a/client/consensus/babe/src/tests.rs b/client/consensus/babe/src/tests.rs index 8bef1b38b929d..47466512ef065 100644 --- a/client/consensus/babe/src/tests.rs +++ b/client/consensus/babe/src/tests.rs @@ -314,7 +314,7 @@ impl TestNetFactory for BabeTestNet { use substrate_test_runtime_client::DefaultTestClientBuilderExt; let client = client.as_client(); - trace!(target: "babe", "Creating a verifier"); + trace!(target: LOG_TARGET, "Creating a verifier"); // ensure block import and verifier are linked correctly. let data = maybe_link @@ -343,12 +343,12 @@ impl TestNetFactory for BabeTestNet { } fn peer(&mut self, i: usize) -> &mut BabePeer { - trace!(target: "babe", "Retrieving a peer"); + trace!(target: LOG_TARGET, "Retrieving a peer"); &mut self.peers[i] } fn peers(&self) -> &Vec { - trace!(target: "babe", "Retrieving peers"); + trace!(target: LOG_TARGET, "Retrieving peers"); &self.peers } @@ -571,7 +571,7 @@ fn can_author_block() { // with secondary slots enabled it should never be empty match claim_slot(i.into(), &epoch, &keystore) { None => i += 1, - Some(s) => debug!(target: "babe", "Authored block {:?}", s.0), + Some(s) => debug!(target: LOG_TARGET, "Authored block {:?}", s.0), } // otherwise with only vrf-based primary slots we might need to try a couple @@ -581,7 +581,7 @@ fn can_author_block() { match claim_slot(i.into(), &epoch, &keystore) { None => i += 1, Some(s) => { - debug!(target: "babe", "Authored block {:?}", s.0); + debug!(target: LOG_TARGET, "Authored block {:?}", s.0); break }, } diff --git a/client/consensus/babe/src/verification.rs b/client/consensus/babe/src/verification.rs index 53ec3002e6a85..e77a70c8e465a 100644 --- a/client/consensus/babe/src/verification.rs +++ b/client/consensus/babe/src/verification.rs @@ -17,9 +17,9 @@ // along with this program. If not, see . //! Verification for BABE headers. -use super::{ +use crate::{ authorship::{calculate_primary_threshold, check_primary_threshold, secondary_slot_author}, - babe_err, find_pre_digest, BlockT, Epoch, Error, + babe_err, find_pre_digest, BlockT, Epoch, Error, LOG_TARGET, }; use log::{debug, trace}; use sc_consensus_slots::CheckedHeader; @@ -67,7 +67,7 @@ pub(super) fn check_header( let authorities = &epoch.authorities; let pre_digest = pre_digest.map(Ok).unwrap_or_else(|| find_pre_digest::(&header))?; - trace!(target: "babe", "Checking header"); + trace!(target: LOG_TARGET, "Checking header"); let seal = header .digest_mut() .pop() @@ -93,7 +93,8 @@ pub(super) fn check_header( match &pre_digest { PreDigest::Primary(primary) => { - debug!(target: "babe", + debug!( + target: LOG_TARGET, "Verifying primary block #{} at slot: {}", header.number(), primary.slot, @@ -104,7 +105,8 @@ pub(super) fn check_header( PreDigest::SecondaryPlain(secondary) if epoch.config.allowed_slots.is_secondary_plain_slots_allowed() => { - debug!(target: "babe", + debug!( + target: LOG_TARGET, "Verifying secondary plain block #{} at slot: {}", header.number(), secondary.slot, @@ -115,7 +117,8 @@ pub(super) fn check_header( PreDigest::SecondaryVRF(secondary) if epoch.config.allowed_slots.is_secondary_vrf_slots_allowed() => { - debug!(target: "babe", + debug!( + target: LOG_TARGET, "Verifying secondary VRF block #{} at slot: {}", header.number(), secondary.slot, diff --git a/client/consensus/common/src/import_queue.rs b/client/consensus/common/src/import_queue.rs index 3741fa99663cd..62fcde019b9f1 100644 --- a/client/consensus/common/src/import_queue.rs +++ b/client/consensus/common/src/import_queue.rs @@ -45,6 +45,8 @@ use crate::{ pub use basic_queue::BasicQueue; use sp_consensus::{error::Error as ConsensusError, BlockOrigin, CacheKeyId}; +const LOG_TARGET: &str = "import-queue"; + /// A commonly-used Import Queue type. /// /// This defines the transaction type of the `BasicQueue` to be the transaction type for a client. @@ -232,15 +234,15 @@ pub(crate) async fn import_single_block_metered< (Some(header), justifications) => (header, justifications), (None, _) => { if let Some(ref peer) = peer { - debug!(target: "sync", "Header {} was not provided by {} ", block.hash, peer); + debug!(target: LOG_TARGET, "Header {} was not provided by {} ", block.hash, peer); } else { - debug!(target: "sync", "Header {} was not provided ", block.hash); + debug!(target: LOG_TARGET, "Header {} was not provided ", block.hash); } return Err(BlockImportError::IncompleteHeader(peer)) }, }; - trace!(target: "sync", "Header {} has {:?} logs", block.hash, header.digest().logs().len()); + trace!(target: LOG_TARGET, "Header {} has {:?} logs", block.hash, header.digest().logs().len()); let number = *header.number(); let hash = block.hash; @@ -248,27 +250,31 @@ pub(crate) async fn import_single_block_metered< let import_handler = |import| match import { Ok(ImportResult::AlreadyInChain) => { - trace!(target: "sync", "Block already in chain {}: {:?}", number, hash); + trace!(target: LOG_TARGET, "Block already in chain {}: {:?}", number, hash); Ok(BlockImportStatus::ImportedKnown(number, peer)) }, Ok(ImportResult::Imported(aux)) => Ok(BlockImportStatus::ImportedUnknown(number, aux, peer)), Ok(ImportResult::MissingState) => { - debug!(target: "sync", "Parent state is missing for {}: {:?}, parent: {:?}", - number, hash, parent_hash); + debug!( + target: LOG_TARGET, + "Parent state is missing for {}: {:?}, parent: {:?}", number, hash, parent_hash + ); Err(BlockImportError::MissingState) }, Ok(ImportResult::UnknownParent) => { - debug!(target: "sync", "Block with unknown parent {}: {:?}, parent: {:?}", - number, hash, parent_hash); + debug!( + target: LOG_TARGET, + "Block with unknown parent {}: {:?}, parent: {:?}", number, hash, parent_hash + ); Err(BlockImportError::UnknownParent) }, Ok(ImportResult::KnownBad) => { - debug!(target: "sync", "Peer gave us a bad block {}: {:?}", number, hash); + debug!(target: LOG_TARGET, "Peer gave us a bad block {}: {:?}", number, hash); Err(BlockImportError::BadBlock(peer)) }, Err(e) => { - debug!(target: "sync", "Error importing block {}: {:?}: {}", number, hash, e); + debug!(target: LOG_TARGET, "Error importing block {}: {:?}: {}", number, hash, e); Err(BlockImportError::Other(e)) }, }; @@ -309,9 +315,16 @@ pub(crate) async fn import_single_block_metered< let (import_block, maybe_keys) = verifier.verify(import_block).await.map_err(|msg| { if let Some(ref peer) = peer { - trace!(target: "sync", "Verifying {}({}) from {} failed: {}", number, hash, peer, msg); + trace!( + target: LOG_TARGET, + "Verifying {}({}) from {} failed: {}", + number, + hash, + peer, + msg + ); } else { - trace!(target: "sync", "Verifying {}({}) failed: {}", number, hash, msg); + trace!(target: LOG_TARGET, "Verifying {}({}) failed: {}", number, hash, msg); } if let Some(metrics) = metrics.as_ref() { metrics.report_verification(false, started.elapsed()); diff --git a/client/consensus/common/src/import_queue/basic_queue.rs b/client/consensus/common/src/import_queue/basic_queue.rs index 0e607159b75c3..885f887f8e9ca 100644 --- a/client/consensus/common/src/import_queue/basic_queue.rs +++ b/client/consensus/common/src/import_queue/basic_queue.rs @@ -35,6 +35,7 @@ use crate::{ buffered_link::{self, BufferedLinkReceiver, BufferedLinkSender}, import_single_block_metered, BlockImportError, BlockImportStatus, BoxBlockImport, BoxJustificationImport, ImportQueue, IncomingBlock, Link, RuntimeOrigin, Verifier, + LOG_TARGET, }, metrics::Metrics, }; @@ -105,14 +106,14 @@ impl ImportQueue for BasicQueue return } - trace!(target: "sync", "Scheduling {} blocks for import", blocks.len()); + trace!(target: LOG_TARGET, "Scheduling {} blocks for import", blocks.len()); let res = self .block_import_sender .unbounded_send(worker_messages::ImportBlocks(origin, blocks)); if res.is_err() { log::error!( - target: "sync", + target: LOG_TARGET, "import_blocks: Background import task is no longer alive" ); } @@ -132,7 +133,7 @@ impl ImportQueue for BasicQueue if res.is_err() { log::error!( - target: "sync", + target: LOG_TARGET, "import_justification: Background import task is no longer alive" ); } @@ -141,7 +142,10 @@ impl ImportQueue for BasicQueue fn poll_actions(&mut self, cx: &mut Context, link: &mut dyn Link) { if self.result_port.poll_actions(cx, link).is_err() { - log::error!(target: "sync", "poll_actions: Background import task is no longer alive"); + log::error!( + target: LOG_TARGET, + "poll_actions: Background import task is no longer alive" + ); } } } @@ -180,7 +184,7 @@ async fn block_import_process( Some(blocks) => blocks, None => { log::debug!( - target: "block-import", + target: LOG_TARGET, "Stopping block import because the import channel was closed!", ); return @@ -254,7 +258,7 @@ impl BlockImportWorker { // down and we should end this future. if worker.result_sender.is_closed() { log::debug!( - target: "block-import", + target: LOG_TARGET, "Stopping block import because result channel was closed!", ); return @@ -267,7 +271,7 @@ impl BlockImportWorker { worker.import_justification(who, hash, number, justification).await, None => { log::debug!( - target: "block-import", + target: LOG_TARGET, "Stopping block import because justification channel was closed!", ); return @@ -302,7 +306,7 @@ impl BlockImportWorker { .await .map_err(|e| { debug!( - target: "sync", + target: LOG_TARGET, "Justification import failed for hash = {:?} with number = {:?} coming from node = {:?} with error: {}", hash, number, @@ -356,7 +360,7 @@ async fn import_many_blocks, Transaction: Send + 'stat _ => Default::default(), }; - trace!(target: "sync", "Starting import of {} blocks {}", count, blocks_range); + trace!(target: LOG_TARGET, "Starting import of {} blocks {}", count, blocks_range); let mut imported = 0; let mut results = vec![]; @@ -396,7 +400,7 @@ async fn import_many_blocks, Transaction: Send + 'stat if import_result.is_ok() { trace!( - target: "sync", + target: LOG_TARGET, "Block imported successfully {:?} ({})", block_number, block_hash, diff --git a/client/consensus/manual-seal/src/consensus/babe.rs b/client/consensus/manual-seal/src/consensus/babe.rs index 206f5163a13cd..d2bea3a3a3656 100644 --- a/client/consensus/manual-seal/src/consensus/babe.rs +++ b/client/consensus/manual-seal/src/consensus/babe.rs @@ -20,7 +20,7 @@ //! that expect babe-specific digests. use super::ConsensusDataProvider; -use crate::Error; +use crate::{Error, LOG_TARGET}; use codec::Encode; use sc_client_api::{AuxStore, UsageProvider}; use sc_consensus_babe::{ @@ -179,7 +179,7 @@ where let epoch = epoch_changes .viable_epoch(&epoch_descriptor, |slot| Epoch::genesis(&self.config, slot)) .ok_or_else(|| { - log::info!(target: "babe", "create_digest: no viable_epoch :("); + log::info!(target: LOG_TARGET, "create_digest: no viable_epoch :("); sp_consensus::Error::InvalidAuthoritiesSet })?; @@ -290,7 +290,7 @@ where let has_authority = epoch.authorities.iter().any(|(id, _)| *id == *authority); if !has_authority { - log::info!(target: "manual-seal", "authority not found"); + log::info!(target: LOG_TARGET, "authority not found"); let timestamp = inherents .timestamp_inherent_data()? .ok_or_else(|| Error::StringError("No timestamp inherent data".into()))?; diff --git a/client/consensus/manual-seal/src/lib.rs b/client/consensus/manual-seal/src/lib.rs index 09ab139b91c73..700b94cf1d704 100644 --- a/client/consensus/manual-seal/src/lib.rs +++ b/client/consensus/manual-seal/src/lib.rs @@ -49,6 +49,8 @@ pub use self::{ use sc_transaction_pool_api::TransactionPool; use sp_api::{ProvideRuntimeApi, TransactionFor}; +const LOG_TARGET: &str = "manual-seal"; + /// The `ConsensusEngineId` of Manual Seal. pub const MANUAL_SEAL_ENGINE_ID: ConsensusEngineId = [b'm', b'a', b'n', b'l']; diff --git a/client/consensus/pow/src/lib.rs b/client/consensus/pow/src/lib.rs index dcf069d617bab..91739eeb7f85f 100644 --- a/client/consensus/pow/src/lib.rs +++ b/client/consensus/pow/src/lib.rs @@ -67,6 +67,8 @@ use sp_runtime::{ }; use std::{cmp::Ordering, collections::HashMap, marker::PhantomData, sync::Arc, time::Duration}; +const LOG_TARGET: &str = "pow"; + #[derive(Debug, thiserror::Error)] pub enum Error { #[error("Header uses the wrong engine {0:?}")] @@ -530,7 +532,7 @@ where } if sync_oracle.is_major_syncing() { - debug!(target: "pow", "Skipping proposal due to sync."); + debug!(target: LOG_TARGET, "Skipping proposal due to sync."); worker.on_major_syncing(); continue } @@ -539,7 +541,7 @@ where Ok(x) => x, Err(err) => { warn!( - target: "pow", + target: LOG_TARGET, "Unable to pull new block for authoring. \ Select best chain error: {}", err @@ -560,7 +562,7 @@ where Ok(x) => x, Err(err) => { warn!( - target: "pow", + target: LOG_TARGET, "Unable to propose new block for authoring. \ Fetch difficulty failed: {}", err, @@ -576,7 +578,7 @@ where Ok(x) => x, Err(err) => { warn!( - target: "pow", + target: LOG_TARGET, "Unable to propose new block for authoring. \ Creating inherent data providers failed: {}", err, @@ -589,7 +591,7 @@ where Ok(r) => r, Err(e) => { warn!( - target: "pow", + target: LOG_TARGET, "Unable to propose new block for authoring. \ Creating inherent data failed: {}", e, @@ -609,7 +611,7 @@ where Ok(x) => x, Err(err) => { warn!( - target: "pow", + target: LOG_TARGET, "Unable to propose new block for authoring. \ Creating proposer failed: {:?}", err, @@ -623,7 +625,7 @@ where Ok(x) => x, Err(err) => { warn!( - target: "pow", + target: LOG_TARGET, "Unable to propose new block for authoring. \ Creating proposal failed: {}", err, @@ -653,14 +655,14 @@ where fn find_pre_digest(header: &B::Header) -> Result>, Error> { let mut pre_digest: Option<_> = None; for log in header.digest().logs() { - trace!(target: "pow", "Checking log {:?}, looking for pre runtime digest", log); + trace!(target: LOG_TARGET, "Checking log {:?}, looking for pre runtime digest", log); match (log, pre_digest.is_some()) { (DigestItem::PreRuntime(POW_ENGINE_ID, _), true) => return Err(Error::MultiplePreRuntimeDigests), (DigestItem::PreRuntime(POW_ENGINE_ID, v), false) => { pre_digest = Some(v.clone()); }, - (_, _) => trace!(target: "pow", "Ignoring digest not meant for us"), + (_, _) => trace!(target: LOG_TARGET, "Ignoring digest not meant for us"), } } diff --git a/client/consensus/pow/src/worker.rs b/client/consensus/pow/src/worker.rs index a00da6e7022fb..b53227bb3ca50 100644 --- a/client/consensus/pow/src/worker.rs +++ b/client/consensus/pow/src/worker.rs @@ -41,7 +41,7 @@ use std::{ time::Duration, }; -use crate::{PowAlgorithm, PowIntermediate, Seal, INTERMEDIATE_KEY, POW_ENGINE_ID}; +use crate::{PowAlgorithm, PowIntermediate, Seal, INTERMEDIATE_KEY, LOG_TARGET, POW_ENGINE_ID}; /// Mining metadata. This is the information needed to start an actual mining loop. #[derive(Clone, Eq, PartialEq)] @@ -159,26 +159,16 @@ where ) { Ok(true) => (), Ok(false) => { - warn!( - target: "pow", - "Unable to import mined block: seal is invalid", - ); + warn!(target: LOG_TARGET, "Unable to import mined block: seal is invalid",); return false }, Err(err) => { - warn!( - target: "pow", - "Unable to import mined block: {}", - err, - ); + warn!(target: LOG_TARGET, "Unable to import mined block: {}", err,); return false }, } } else { - warn!( - target: "pow", - "Unable to import mined block: metadata does not exist", - ); + warn!(target: LOG_TARGET, "Unable to import mined block: metadata does not exist",); return false } @@ -192,10 +182,7 @@ where } { build } else { - warn!( - target: "pow", - "Unable to import mined block: build does not exist", - ); + warn!(target: LOG_TARGET, "Unable to import mined block: build does not exist",); return false }; @@ -225,18 +212,13 @@ where ); info!( - target: "pow", - "✅ Successfully mined block on top of: {}", - build.metadata.best_hash + target: LOG_TARGET, + "✅ Successfully mined block on top of: {}", build.metadata.best_hash ); true }, Err(err) => { - warn!( - target: "pow", - "Unable to import mined block: {}", - err, - ); + warn!(target: LOG_TARGET, "Unable to import mined block: {}", err,); false }, } diff --git a/client/consensus/slots/src/lib.rs b/client/consensus/slots/src/lib.rs index 90bfef6c1609c..6627341816555 100644 --- a/client/consensus/slots/src/lib.rs +++ b/client/consensus/slots/src/lib.rs @@ -44,6 +44,8 @@ use sp_inherents::CreateInherentDataProviders; use sp_runtime::traits::{Block as BlockT, HashFor, Header as HeaderT}; use std::{fmt::Debug, ops::Deref, time::Duration}; +const LOG_TARGET: &str = "slots"; + /// The changes that need to applied to the storage to create the state for a block. /// /// See [`sp_state_machine::StorageChanges`] for more information. @@ -194,7 +196,7 @@ pub trait SimpleSlotWorker { > { let slot = slot_info.slot; let telemetry = self.telemetry(); - let logging_target = self.logging_target(); + let log_target = self.logging_target(); let proposing_remaining_duration = self.proposing_remaining_duration(&slot_info); let logs = self.pre_digest_data(slot, claim); @@ -213,19 +215,19 @@ pub trait SimpleSlotWorker { let proposal = match futures::future::select(proposing, proposing_remaining).await { Either::Left((Ok(p), _)) => p, Either::Left((Err(err), _)) => { - warn!(target: logging_target, "Proposing failed: {}", err); + warn!(target: log_target, "Proposing failed: {}", err); return None }, Either::Right(_) => { info!( - target: logging_target, + target: log_target, "⌛️ Discarding proposal for slot {}; block production took too long", slot, ); // If the node was compiled with debug, tell the user to use release optimizations. #[cfg(build_type = "debug")] info!( - target: logging_target, + target: log_target, "👉 Recompile your node in `--release` mode to mitigate this problem.", ); telemetry!( @@ -483,13 +485,13 @@ pub async fn start_slot_worker( let slot_info = match slots.next_slot().await { Ok(r) => r, Err(e) => { - warn!(target: "slots", "Error while polling for next slot: {}", e); + warn!(target: LOG_TARGET, "Error while polling for next slot: {}", e); return }, }; if sync_oracle.is_major_syncing() { - debug!(target: "slots", "Skipping proposal slot due to sync."); + debug!(target: LOG_TARGET, "Skipping proposal slot due to sync."); continue } diff --git a/client/consensus/slots/src/slots.rs b/client/consensus/slots/src/slots.rs index f3dc485a8e819..54177319cb2b1 100644 --- a/client/consensus/slots/src/slots.rs +++ b/client/consensus/slots/src/slots.rs @@ -20,7 +20,7 @@ //! //! This is used instead of `futures_timer::Interval` because it was unreliable. -use super::{InherentDataProviderExt, Slot}; +use super::{InherentDataProviderExt, Slot, LOG_TARGET}; use sp_consensus::{Error, SelectChain}; use sp_inherents::{CreateInherentDataProviders, InherentData, InherentDataProvider}; use sp_runtime::traits::{Block as BlockT, Header as HeaderT}; @@ -149,7 +149,7 @@ where Ok(x) => x, Err(e) => { log::warn!( - target: "slots", + target: LOG_TARGET, "Unable to author block in slot. No best block header: {}", e, ); @@ -166,7 +166,7 @@ where if Instant::now() > ends_at { log::warn!( - target: "slots", + target: LOG_TARGET, "Creating inherent data providers took more time than we had left for the slot.", ); } diff --git a/client/finality-grandpa/src/authorities.rs b/client/finality-grandpa/src/authorities.rs index 0803e6b3c2931..a61c66979bb5c 100644 --- a/client/finality-grandpa/src/authorities.rs +++ b/client/finality-grandpa/src/authorities.rs @@ -29,7 +29,7 @@ use sc_consensus::shared_data::{SharedData, SharedDataLocked}; use sc_telemetry::{telemetry, TelemetryHandle, CONSENSUS_INFO}; use sp_finality_grandpa::{AuthorityId, AuthorityList}; -use crate::SetId; +use crate::{SetId, LOG_TARGET}; /// Error type returned on operations on the `AuthoritySet`. #[derive(Debug, thiserror::Error)] @@ -314,7 +314,7 @@ where let number = pending.canon_height.clone(); debug!( - target: "afg", + target: LOG_TARGET, "Inserting potential standard set change signaled at block {:?} (delayed by {:?} blocks).", (&number, &hash), pending.delay, @@ -323,7 +323,7 @@ where self.pending_standard_changes.import(hash, number, pending, is_descendent_of)?; debug!( - target: "afg", + target: LOG_TARGET, "There are now {} alternatives for the next pending standard change (roots), and a \ total of {} pending standard changes (across all forks).", self.pending_standard_changes.roots().count(), @@ -362,7 +362,7 @@ where .unwrap_or_else(|i| i); debug!( - target: "afg", + target: LOG_TARGET, "Inserting potential forced set change at block {:?} (delayed by {:?} blocks).", (&pending.canon_height, &pending.canon_hash), pending.delay, @@ -370,7 +370,11 @@ where self.pending_forced_changes.insert(idx, pending); - debug!(target: "afg", "There are now {} pending forced changes.", self.pending_forced_changes.len()); + debug!( + target: LOG_TARGET, + "There are now {} pending forced changes.", + self.pending_forced_changes.len() + ); Ok(()) } @@ -475,7 +479,7 @@ where if standard_change.effective_number() <= median_last_finalized && is_descendent_of(&standard_change.canon_hash, &change.canon_hash)? { - log::info!(target: "afg", + log::info!(target: LOG_TARGET, "Not applying authority set change forced at block #{:?}, due to pending standard change at block #{:?}", change.canon_height, standard_change.effective_number(), @@ -488,7 +492,7 @@ where } // apply this change: make the set canonical - afg_log!( + grandpa_log!( initial_sync, "👴 Applying authority set change forced at block #{:?}", change.canon_height, @@ -570,7 +574,7 @@ where } if let Some(change) = change { - afg_log!( + grandpa_log!( initial_sync, "👴 Applying authority set change scheduled at block #{:?}", change.canon_height, diff --git a/client/finality-grandpa/src/aux_schema.rs b/client/finality-grandpa/src/aux_schema.rs index 235453ea35df1..a7357a7fa5e40 100644 --- a/client/finality-grandpa/src/aux_schema.rs +++ b/client/finality-grandpa/src/aux_schema.rs @@ -38,7 +38,7 @@ use crate::{ CompletedRound, CompletedRounds, CurrentRounds, HasVoted, SharedVoterSetState, VoterSetState, }, - GrandpaJustification, NewAuthoritySet, + GrandpaJustification, NewAuthoritySet, LOG_TARGET, }; const VERSION_KEY: &[u8] = b"grandpa_schema_version"; @@ -100,8 +100,8 @@ where // previously we only supported at most one pending change per fork &|_, _| Ok(false), ) { - warn!(target: "afg", "Error migrating pending authority set change: {}", err); - warn!(target: "afg", "Node is in a potentially inconsistent state."); + warn!(target: LOG_TARGET, "Error migrating pending authority set change: {}", err); + warn!(target: LOG_TARGET, "Node is in a potentially inconsistent state."); } } @@ -384,8 +384,11 @@ where } // genesis. - info!(target: "afg", "👴 Loading GRANDPA authority set \ - from genesis on what appears to be first startup."); + info!( + target: LOG_TARGET, + "👴 Loading GRANDPA authority set \ + from genesis on what appears to be first startup." + ); let genesis_authorities = genesis_authorities()?; let genesis_set = AuthoritySet::genesis(genesis_authorities) diff --git a/client/finality-grandpa/src/communication/gossip.rs b/client/finality-grandpa/src/communication/gossip.rs index 218b4b668c10f..408cbda745e56 100644 --- a/client/finality-grandpa/src/communication/gossip.rs +++ b/client/finality-grandpa/src/communication/gossip.rs @@ -99,7 +99,7 @@ use sp_finality_grandpa::AuthorityId; use sp_runtime::traits::{Block as BlockT, NumberFor, Zero}; use super::{benefit, cost, Round, SetId, NEIGHBOR_REBROADCAST_PERIOD}; -use crate::{environment, CatchUp, CompactCommit, SignedMessage}; +use crate::{environment, CatchUp, CompactCommit, SignedMessage, LOG_TARGET}; use std::{ collections::{HashSet, VecDeque}, @@ -578,8 +578,13 @@ impl Peers { last_update: Some(now), }; - trace!(target: "afg", "Peer {} updated view. Now at {:?}, {:?}", - who, peer.view.round, peer.view.set_id); + trace!( + target: LOG_TARGET, + "Peer {} updated view. Now at {:?}, {:?}", + who, + peer.view.round, + peer.view.set_id + ); Ok(Some(&peer.view)) } @@ -801,8 +806,12 @@ impl Inner { let set_id = local_view.set_id; - debug!(target: "afg", "Voter {} noting beginning of round {:?} to network.", - self.config.name(), (round, set_id)); + debug!( + target: LOG_TARGET, + "Voter {} noting beginning of round {:?} to network.", + self.config.name(), + (round, set_id) + ); local_view.update_round(round); @@ -824,7 +833,7 @@ impl Inner { authorities.iter().collect::>(); if diff_authorities { - debug!(target: "afg", + debug!(target: LOG_TARGET, "Gossip validator noted set {:?} twice with different authorities. \ Was the authority set hard forked?", set_id, @@ -912,7 +921,7 @@ impl Inner { // ensure authority is part of the set. if !self.authorities.contains(&full.message.id) { - debug!(target: "afg", "Message from unknown voter: {}", full.message.id); + debug!(target: LOG_TARGET, "Message from unknown voter: {}", full.message.id); telemetry!( self.config.telemetry; CONSENSUS_DEBUG; @@ -929,7 +938,7 @@ impl Inner { full.round.0, full.set_id.0, ) { - debug!(target: "afg", "Bad message signature {}", full.message.id); + debug!(target: LOG_TARGET, "Bad message signature {}", full.message.id); telemetry!( self.config.telemetry; CONSENSUS_DEBUG; @@ -964,7 +973,7 @@ impl Inner { if full.message.precommits.len() != full.message.auth_data.len() || full.message.precommits.is_empty() { - debug!(target: "afg", "Malformed compact commit"); + debug!(target: LOG_TARGET, "Malformed compact commit"); telemetry!( self.config.telemetry; CONSENSUS_DEBUG; @@ -1023,9 +1032,9 @@ impl Inner { PendingCatchUp::Processing { .. } => { self.pending_catch_up = PendingCatchUp::None; }, - state => debug!(target: "afg", - "Noted processed catch up message when state was: {:?}", - state, + state => debug!( + target: LOG_TARGET, + "Noted processed catch up message when state was: {:?}", state, ), } } @@ -1067,7 +1076,9 @@ impl Inner { return (None, Action::Discard(Misbehavior::OutOfScopeMessage.cost())) } - trace!(target: "afg", "Replying to catch-up request for round {} from {} with round {}", + trace!( + target: LOG_TARGET, + "Replying to catch-up request for round {} from {} with round {}", request.round.0, who, last_completed_round.number, @@ -1141,9 +1152,9 @@ impl Inner { let (catch_up_allowed, catch_up_report) = self.note_catch_up_request(who, &request); if catch_up_allowed { - debug!(target: "afg", "Sending catch-up request for round {} to {}", - round, - who, + debug!( + target: LOG_TARGET, + "Sending catch-up request for round {} to {}", round, who, ); catch_up = Some(GossipMessage::::CatchUpRequest(request)); @@ -1347,7 +1358,7 @@ impl GossipValidator { let metrics = match prometheus_registry.map(Metrics::register) { Some(Ok(metrics)) => Some(metrics), Some(Err(e)) => { - debug!(target: "afg", "Failed to register metrics: {:?}", e); + debug!(target: LOG_TARGET, "Failed to register metrics: {:?}", e); None }, None => None, @@ -1466,7 +1477,7 @@ impl GossipValidator { }, Err(e) => { message_name = None; - debug!(target: "afg", "Error decoding message: {}", e); + debug!(target: LOG_TARGET, "Error decoding message: {}", e); telemetry!( self.telemetry; CONSENSUS_DEBUG; diff --git a/client/finality-grandpa/src/communication/mod.rs b/client/finality-grandpa/src/communication/mod.rs index 75a7697812c6c..e7e3c12989c96 100644 --- a/client/finality-grandpa/src/communication/mod.rs +++ b/client/finality-grandpa/src/communication/mod.rs @@ -54,7 +54,7 @@ use sp_runtime::traits::{Block as BlockT, Hash as HashT, Header as HeaderT, Numb use crate::{ environment::HasVoted, CatchUp, Commit, CommunicationIn, CommunicationOutH, CompactCommit, - Error, Message, SignedMessage, + Error, Message, SignedMessage, LOG_TARGET, }; use gossip::{ FullCatchUpMessage, FullCommitMessage, GossipMessage, GossipValidator, PeerReport, VoteMessage, @@ -274,7 +274,8 @@ impl> NetworkBridge { gossip_engine.lock().register_gossip_message(topic, message.encode()); } - trace!(target: "afg", + trace!( + target: LOG_TARGET, "Registered {} messages for topic {:?} (round: {}, set_id: {})", round.votes.len(), topic, @@ -340,13 +341,19 @@ impl> NetworkBridge { match decoded { Err(ref e) => { - debug!(target: "afg", "Skipping malformed message {:?}: {}", notification, e); + debug!( + target: LOG_TARGET, + "Skipping malformed message {:?}: {}", notification, e + ); future::ready(None) }, Ok(GossipMessage::Vote(msg)) => { // check signature. if !voters.contains(&msg.message.id) { - debug!(target: "afg", "Skipping message from unknown voter {}", msg.message.id); + debug!( + target: LOG_TARGET, + "Skipping message from unknown voter {}", msg.message.id + ); return future::ready(None) } @@ -388,7 +395,7 @@ impl> NetworkBridge { future::ready(Some(msg.message)) }, _ => { - debug!(target: "afg", "Skipping unknown message type"); + debug!(target: LOG_TARGET, "Skipping unknown message type"); future::ready(None) }, } @@ -631,7 +638,12 @@ fn incoming_global( // this could be optimized by decoding piecewise. let decoded = GossipMessage::::decode(&mut ¬ification.message[..]); if let Err(ref e) = decoded { - trace!(target: "afg", "Skipping malformed commit message {:?}: {}", notification, e); + trace!( + target: LOG_TARGET, + "Skipping malformed commit message {:?}: {}", + notification, + e + ); } future::ready(decoded.map(move |d| (notification, d)).ok()) }) @@ -642,7 +654,7 @@ fn incoming_global( GossipMessage::CatchUp(msg) => process_catch_up(msg, notification, &gossip_engine, &gossip_validator, &voters), _ => { - debug!(target: "afg", "Skipping unknown message type"); + debug!(target: LOG_TARGET, "Skipping unknown message type"); None }, }) @@ -748,7 +760,7 @@ impl Sink> for OutgoingMessages { }); debug!( - target: "afg", + target: LOG_TARGET, "Announcing block {} to peers which we voted on in round {} in set {}", target_hash, self.round, @@ -813,7 +825,7 @@ fn check_compact_commit( return Err(cost::MALFORMED_COMMIT) } } else { - debug!(target: "afg", "Skipping commit containing unknown voter {}", id); + debug!(target: LOG_TARGET, "Skipping commit containing unknown voter {}", id); return Err(cost::MALFORMED_COMMIT) } } @@ -838,7 +850,7 @@ fn check_compact_commit( set_id.0, &mut buf, ) { - debug!(target: "afg", "Bad commit message signature {}", id); + debug!(target: LOG_TARGET, "Bad commit message signature {}", id); telemetry!( telemetry; CONSENSUS_DEBUG; @@ -886,7 +898,10 @@ fn check_catch_up( return Err(cost::MALFORMED_CATCH_UP) } } else { - debug!(target: "afg", "Skipping catch up message containing unknown voter {}", id); + debug!( + target: LOG_TARGET, + "Skipping catch up message containing unknown voter {}", id + ); return Err(cost::MALFORMED_CATCH_UP) } } @@ -922,7 +937,7 @@ fn check_catch_up( if !sp_finality_grandpa::check_message_signature_with_buffer( &msg, id, sig, round, set_id, buf, ) { - debug!(target: "afg", "Bad catch up message signature {}", id); + debug!(target: LOG_TARGET, "Bad catch up message signature {}", id); telemetry!( telemetry; CONSENSUS_DEBUG; diff --git a/client/finality-grandpa/src/communication/periodic.rs b/client/finality-grandpa/src/communication/periodic.rs index c001796b5ca5d..7e50abb96e441 100644 --- a/client/finality-grandpa/src/communication/periodic.rs +++ b/client/finality-grandpa/src/communication/periodic.rs @@ -21,17 +21,19 @@ use futures::{future::FutureExt as _, prelude::*, ready, stream::Stream}; use futures_timer::Delay; use log::debug; -use sc_utils::mpsc::{tracing_unbounded, TracingUnboundedReceiver, TracingUnboundedSender}; use std::{ pin::Pin, task::{Context, Poll}, time::Duration, }; -use super::gossip::{GossipMessage, NeighborPacket}; use sc_network::PeerId; +use sc_utils::mpsc::{tracing_unbounded, TracingUnboundedReceiver, TracingUnboundedSender}; use sp_runtime::traits::{Block as BlockT, NumberFor}; +use super::gossip::{GossipMessage, NeighborPacket}; +use crate::LOG_TARGET; + /// A sender used to send neighbor packets to a background job. #[derive(Clone)] pub(super) struct NeighborPacketSender( @@ -46,7 +48,7 @@ impl NeighborPacketSender { neighbor_packet: NeighborPacket>, ) { if let Err(err) = self.0.unbounded_send((who, neighbor_packet)) { - debug!(target: "afg", "Failed to send neighbor packet: {:?}", err); + debug!(target: LOG_TARGET, "Failed to send neighbor packet: {:?}", err); } } } diff --git a/client/finality-grandpa/src/environment.rs b/client/finality-grandpa/src/environment.rs index f235c3a86c04e..110d0eb2c927e 100644 --- a/client/finality-grandpa/src/environment.rs +++ b/client/finality-grandpa/src/environment.rs @@ -60,7 +60,7 @@ use crate::{ until_imported::UntilVoteTargetImported, voting_rule::VotingRule as VotingRuleT, ClientForGrandpa, CommandOrError, Commit, Config, Error, NewAuthoritySet, Precommit, Prevote, - PrimaryPropose, SignedMessage, VoterCommand, + PrimaryPropose, SignedMessage, VoterCommand, LOG_TARGET, }; type HistoricalVotes = finality_grandpa::HistoricalVotes< @@ -551,7 +551,10 @@ where { Some(proof) => proof, None => { - debug!(target: "afg", "Equivocation offender is not part of the authority set."); + debug!( + target: LOG_TARGET, + "Equivocation offender is not part of the authority set." + ); return Ok(()) }, }; @@ -609,8 +612,13 @@ where let tree_route = match tree_route_res { Ok(tree_route) => tree_route, Err(e) => { - debug!(target: "afg", "Encountered error computing ancestry between block {:?} and base {:?}: {}", - block, base, e); + debug!( + target: LOG_TARGET, + "Encountered error computing ancestry between block {:?} and base {:?}: {}", + block, + base, + e + ); return Err(GrandpaError::NotDescendent) }, @@ -955,7 +963,8 @@ where historical_votes: &HistoricalVotes, ) -> Result<(), Self::Error> { debug!( - target: "afg", "Voter {} completed round {} in set {}. Estimate = {:?}, Finalized in round = {:?}", + target: LOG_TARGET, + "Voter {} completed round {} in set {}. Estimate = {:?}, Finalized in round = {:?}", self.config.name(), round, self.set_id, @@ -1016,7 +1025,8 @@ where historical_votes: &HistoricalVotes, ) -> Result<(), Self::Error> { debug!( - target: "afg", "Voter {} concluded round {} in set {}. Estimate = {:?}, Finalized in round = {:?}", + target: LOG_TARGET, + "Voter {} concluded round {} in set {}. Estimate = {:?}, Finalized in round = {:?}", self.config.name(), round, self.set_id, @@ -1102,9 +1112,12 @@ where Self::Signature, >, ) { - warn!(target: "afg", "Detected prevote equivocation in the finality worker: {:?}", equivocation); + warn!( + target: LOG_TARGET, + "Detected prevote equivocation in the finality worker: {:?}", equivocation + ); if let Err(err) = self.report_equivocation(equivocation.into()) { - warn!(target: "afg", "Error reporting prevote equivocation: {}", err); + warn!(target: LOG_TARGET, "Error reporting prevote equivocation: {}", err); } } @@ -1117,9 +1130,12 @@ where Self::Signature, >, ) { - warn!(target: "afg", "Detected precommit equivocation in the finality worker: {:?}", equivocation); + warn!( + target: LOG_TARGET, + "Detected precommit equivocation in the finality worker: {:?}", equivocation + ); if let Err(err) = self.report_equivocation(equivocation.into()) { - warn!(target: "afg", "Error reporting precommit equivocation: {}", err); + warn!(target: LOG_TARGET, "Error reporting precommit equivocation: {}", err); } } } @@ -1158,7 +1174,8 @@ where let base_header = match client.header(BlockId::Hash(block))? { Some(h) => h, None => { - debug!(target: "afg", + debug!( + target: LOG_TARGET, "Encountered error finding best chain containing {:?}: couldn't find base block", block, ); @@ -1172,7 +1189,10 @@ where // proceed onwards. most of the time there will be no pending transition. the limit, if any, is // guaranteed to be higher than or equal to the given base number. let limit = authority_set.current_limit(*base_header.number()); - debug!(target: "afg", "Finding best chain containing block {:?} with number limit {:?}", block, limit); + debug!( + target: LOG_TARGET, + "Finding best chain containing block {:?} with number limit {:?}", block, limit + ); let result = match select_chain.finality_target(block, None).await { Ok(best_hash) => { @@ -1234,7 +1254,10 @@ where .or_else(|| Some((target_header.hash(), *target_header.number()))) }, Err(e) => { - warn!(target: "afg", "Encountered error finding best chain containing {:?}: {}", block, e); + warn!( + target: LOG_TARGET, + "Encountered error finding best chain containing {:?}: {}", block, e + ); None }, }; @@ -1273,7 +1296,7 @@ where // This can happen after a forced change (triggered manually from the runtime when // finality is stalled), since the voter will be restarted at the median last finalized // block, which can be lower than the local best finalized block. - warn!(target: "afg", "Re-finalized block #{:?} ({:?}) in the canonical chain, current best finalized is #{:?}", + warn!(target: LOG_TARGET, "Re-finalized block #{:?} ({:?}) in the canonical chain, current best finalized is #{:?}", hash, number, status.finalized_number, @@ -1303,7 +1326,10 @@ where ) { if let Some(sender) = justification_sender { if let Err(err) = sender.notify(justification) { - warn!(target: "afg", "Error creating justification for subscriber: {}", err); + warn!( + target: LOG_TARGET, + "Error creating justification for subscriber: {}", err + ); } } } @@ -1354,11 +1380,16 @@ where client .apply_finality(import_op, hash, persisted_justification, true) .map_err(|e| { - warn!(target: "afg", "Error applying finality to block {:?}: {}", (hash, number), e); + warn!( + target: LOG_TARGET, + "Error applying finality to block {:?}: {}", + (hash, number), + e + ); e })?; - debug!(target: "afg", "Finalizing blocks up to ({:?}, {})", number, hash); + debug!(target: LOG_TARGET, "Finalizing blocks up to ({:?}, {})", number, hash); telemetry!( telemetry; @@ -1376,13 +1407,17 @@ where let (new_id, set_ref) = authority_set.current(); if set_ref.len() > 16 { - afg_log!( + grandpa_log!( initial_sync, "👴 Applying GRANDPA set change to new set with {} authorities", set_ref.len(), ); } else { - afg_log!(initial_sync, "👴 Applying GRANDPA set change to new set {:?}", set_ref); + grandpa_log!( + initial_sync, + "👴 Applying GRANDPA set change to new set {:?}", + set_ref + ); } telemetry!( @@ -1411,8 +1446,11 @@ where ); if let Err(e) = write_result { - warn!(target: "afg", "Failed to write updated authority set to disk. Bailing."); - warn!(target: "afg", "Node is in a potentially inconsistent state."); + warn!( + target: LOG_TARGET, + "Failed to write updated authority set to disk. Bailing." + ); + warn!(target: LOG_TARGET, "Node is in a potentially inconsistent state."); return Err(e.into()) } diff --git a/client/finality-grandpa/src/finality_proof.rs b/client/finality-grandpa/src/finality_proof.rs index 453b41bc63468..43ed0ed31993e 100644 --- a/client/finality-grandpa/src/finality_proof.rs +++ b/client/finality-grandpa/src/finality_proof.rs @@ -52,7 +52,7 @@ use crate::{ authorities::{AuthoritySetChangeId, AuthoritySetChanges}, best_justification, justification::GrandpaJustification, - SharedAuthoritySet, + SharedAuthoritySet, LOG_TARGET, }; const MAX_UNKNOWN_HEADERS: usize = 100_000; @@ -163,7 +163,7 @@ where "Requested finality proof for descendant of #{} while we only have finalized #{}.", block, info.finalized_number, ); - trace!(target: "afg", "{}", &err); + trace!(target: LOG_TARGET, "{}", &err); return Err(FinalityProofError::BlockNotYetFinalized) } @@ -175,7 +175,7 @@ where justification } else { trace!( - target: "afg", + target: LOG_TARGET, "No justification found for the latest finalized block. \ Returning empty proof.", ); @@ -194,7 +194,7 @@ where grandpa_justification } else { trace!( - target: "afg", + target: LOG_TARGET, "No justification found when making finality proof for {}. \ Returning empty proof.", block, @@ -205,7 +205,7 @@ where }, AuthoritySetChangeId::Unknown => { warn!( - target: "afg", + target: LOG_TARGET, "AuthoritySetChanges does not cover the requested block #{} due to missing data. \ You need to resync to populate AuthoritySetChanges properly.", block, diff --git a/client/finality-grandpa/src/import.rs b/client/finality-grandpa/src/import.rs index 3715287eea31f..e061c105eeea5 100644 --- a/client/finality-grandpa/src/import.rs +++ b/client/finality-grandpa/src/import.rs @@ -45,6 +45,7 @@ use crate::{ justification::GrandpaJustification, notification::GrandpaJustificationSender, AuthoritySetChanges, ClientForGrandpa, CommandOrError, Error, NewAuthoritySet, VoterCommand, + LOG_TARGET, }; /// A block-import handler for GRANDPA. @@ -589,18 +590,16 @@ where Ok(ImportResult::Imported(aux)) => aux, Ok(r) => { debug!( - target: "afg", - "Restoring old authority set after block import result: {:?}", - r, + target: LOG_TARGET, + "Restoring old authority set after block import result: {:?}", r, ); pending_changes.revert(); return Ok(r) }, Err(e) => { debug!( - target: "afg", - "Restoring old authority set after block import error: {}", - e, + target: LOG_TARGET, + "Restoring old authority set after block import error: {}", e, ); pending_changes.revert(); return Err(ConsensusError::ClientImport(e.to_string())) @@ -665,7 +664,7 @@ where import_res.unwrap_or_else(|err| { if needs_justification { debug!( - target: "afg", + target: LOG_TARGET, "Requesting justification from peers due to imported block #{} that enacts authority set change with invalid justification: {}", number, err @@ -678,7 +677,7 @@ where None => if needs_justification { debug!( - target: "afg", + target: LOG_TARGET, "Imported unjustified block #{} that enacts authority set change, waiting for finality for enactment.", number, ); @@ -803,7 +802,7 @@ where match result { Err(CommandOrError::VoterCommand(command)) => { - afg_log!( + grandpa_log!( initial_sync, "👴 Imported justification for block #{} that triggers \ command {}, signaling voter.", diff --git a/client/finality-grandpa/src/lib.rs b/client/finality-grandpa/src/lib.rs index a7326d57c2bf0..e3d0a8b12883b 100644 --- a/client/finality-grandpa/src/lib.rs +++ b/client/finality-grandpa/src/lib.rs @@ -93,10 +93,12 @@ use std::{ time::Duration, }; +const LOG_TARGET: &str = "grandpa"; + // 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 { +macro_rules! grandpa_log { ($condition:expr, $($msg: expr),+ $(,)?) => { { let log_level = if $condition { @@ -105,7 +107,7 @@ macro_rules! afg_log { log::Level::Info }; - log::log!(target: "afg", log_level, $($msg),+); + log::log!(target: LOG_TARGET, log_level, $($msg),+); } }; } @@ -804,10 +806,11 @@ where ); let voter_work = voter_work.map(|res| match res { - Ok(()) => error!(target: "afg", + Ok(()) => error!( + target: LOG_TARGET, "GRANDPA voter future has concluded naturally, this should be unreachable." ), - Err(e) => error!(target: "afg", "GRANDPA voter error: {}", e), + Err(e) => error!(target: LOG_TARGET, "GRANDPA voter error: {}", e), }); // Make sure that `telemetry_task` doesn't accidentally finish and kill grandpa. @@ -872,7 +875,7 @@ where let metrics = match prometheus_registry.as_ref().map(Metrics::register) { Some(Ok(metrics)) => Some(metrics), Some(Err(e)) => { - debug!(target: "afg", "Failed to register metrics: {:?}", e); + debug!(target: LOG_TARGET, "Failed to register metrics: {:?}", e); None }, None => None, @@ -914,7 +917,12 @@ where /// state. This method should be called when we know that the authority set /// has changed (e.g. as signalled by a voter command). fn rebuild_voter(&mut self) { - debug!(target: "afg", "{}: Starting new voter with set ID {}", self.env.config.name(), self.env.set_id); + debug!( + target: LOG_TARGET, + "{}: Starting new voter with set ID {}", + self.env.config.name(), + self.env.set_id + ); let maybe_authority_id = local_authority_id(&self.env.voters, self.env.config.keystore.as_ref()); @@ -975,7 +983,8 @@ where // Repoint shared_voter_state so that the RPC endpoint can query the state if self.shared_voter_state.reset(voter.voter_state()).is_none() { - info!(target: "afg", + info!( + target: LOG_TARGET, "Timed out trying to update shared GRANDPA voter state. \ RPC endpoints may return stale data." ); @@ -1044,7 +1053,7 @@ where Ok(()) }, VoterCommand::Pause(reason) => { - info!(target: "afg", "Pausing old validator set: {}", reason); + info!(target: LOG_TARGET, "Pausing old validator set: {}", reason); // not racing because old voter is shut down. self.env.update_voter_set_state(|voter_set_state| { diff --git a/client/finality-grandpa/src/observer.rs b/client/finality-grandpa/src/observer.rs index 9bcb03c0555c2..1efb71e5903ec 100644 --- a/client/finality-grandpa/src/observer.rs +++ b/client/finality-grandpa/src/observer.rs @@ -43,7 +43,7 @@ use crate::{ environment, global_communication, notification::GrandpaJustificationSender, ClientForGrandpa, CommandOrError, CommunicationIn, Config, Error, LinkHalf, VoterCommand, - VoterSetState, + VoterSetState, LOG_TARGET, }; struct ObserverChain<'a, Block: BlockT, Client> { @@ -145,7 +145,7 @@ where // proceed processing with new finalized block number future::ok(finalized_number) } else { - debug!(target: "afg", "Received invalid commit: ({:?}, {:?})", round, commit); + debug!(target: LOG_TARGET, "Received invalid commit: ({:?}, {:?})", round, commit); finality_grandpa::process_commit_validation_result(validation_result, callback); @@ -317,7 +317,7 @@ where // update it on-disk in case we restart as validator in the future. self.persistent_data.set_state = match command { VoterCommand::Pause(reason) => { - info!(target: "afg", "Pausing old validator set: {}", reason); + info!(target: LOG_TARGET, "Pausing old validator set: {}", reason); let completed_rounds = self.persistent_data.set_state.read().completed_rounds(); let set_state = VoterSetState::Paused { completed_rounds }; diff --git a/client/finality-grandpa/src/until_imported.rs b/client/finality-grandpa/src/until_imported.rs index df0b63348e94b..95b658e92298a 100644 --- a/client/finality-grandpa/src/until_imported.rs +++ b/client/finality-grandpa/src/until_imported.rs @@ -24,7 +24,7 @@ use super::{ BlockStatus as BlockStatusT, BlockSyncRequester as BlockSyncRequesterT, CommunicationIn, Error, - SignedMessage, + SignedMessage, LOG_TARGET, }; use finality_grandpa::voter; @@ -296,7 +296,7 @@ where let next_log = *last_log + LOG_PENDING_INTERVAL; if Instant::now() >= next_log { debug!( - target: "afg", + target: LOG_TARGET, "Waiting to import block {} before {} {} messages can be imported. \ Requesting network sync service to retrieve block from. \ Possible fork?", @@ -346,7 +346,7 @@ where fn warn_authority_wrong_target(hash: H, id: AuthorityId) { warn!( - target: "afg", + target: LOG_TARGET, "Authority {:?} signed GRANDPA message with \ wrong block number for hash {}", id, diff --git a/frame/aura/src/lib.rs b/frame/aura/src/lib.rs index ff2c5df04a453..635e22c5d58aa 100644 --- a/frame/aura/src/lib.rs +++ b/frame/aura/src/lib.rs @@ -58,6 +58,8 @@ mod tests; pub use pallet::*; +const LOG_TARGET: &str = "runtime::aura"; + #[frame_support::pallet] pub mod pallet { use super::*; @@ -222,7 +224,7 @@ impl OneSessionHandler for Pallet { if last_authorities != next_authorities { if next_authorities.len() as u32 > T::MaxAuthorities::get() { log::warn!( - target: "runtime::aura", + target: LOG_TARGET, "next authorities list larger than {}, truncating", T::MaxAuthorities::get(), ); diff --git a/frame/babe/src/equivocation.rs b/frame/babe/src/equivocation.rs index f55bda751887d..70f087fd461f9 100644 --- a/frame/babe/src/equivocation.rs +++ b/frame/babe/src/equivocation.rs @@ -48,7 +48,7 @@ use sp_staking::{ }; use sp_std::prelude::*; -use crate::{Call, Config, Pallet}; +use crate::{Call, Config, Pallet, LOG_TARGET}; /// A trait with utility methods for handling equivocation reports in BABE. /// The trait provides methods for reporting an offence triggered by a valid @@ -161,15 +161,9 @@ where }; match SubmitTransaction::>::submit_unsigned_transaction(call.into()) { - Ok(()) => log::info!( - target: "runtime::babe", - "Submitted BABE equivocation report.", - ), - Err(e) => log::error!( - target: "runtime::babe", - "Error submitting equivocation report: {:?}", - e, - ), + Ok(()) => log::info!(target: LOG_TARGET, "Submitted BABE equivocation report.",), + Err(e) => + log::error!(target: LOG_TARGET, "Error submitting equivocation report: {:?}", e,), } Ok(()) @@ -192,7 +186,7 @@ impl Pallet { TransactionSource::Local | TransactionSource::InBlock => { /* allowed */ }, _ => { log::warn!( - target: "runtime::babe", + target: LOG_TARGET, "rejecting unsigned report equivocation transaction because it is not local/in-block.", ); diff --git a/frame/babe/src/lib.rs b/frame/babe/src/lib.rs index eadaa036332fa..b147d7e4acb3c 100644 --- a/frame/babe/src/lib.rs +++ b/frame/babe/src/lib.rs @@ -50,6 +50,8 @@ use sp_consensus_vrf::schnorrkel; pub use sp_consensus_babe::{AuthorityId, PUBLIC_KEY_LENGTH, RANDOMNESS_LENGTH, VRF_OUTPUT_LENGTH}; +const LOG_TARGET: &str = "runtime::babe"; + mod default_weights; mod equivocation; mod randomness; diff --git a/frame/grandpa/src/equivocation.rs b/frame/grandpa/src/equivocation.rs index 181d22fba545c..23801a4982a82 100644 --- a/frame/grandpa/src/equivocation.rs +++ b/frame/grandpa/src/equivocation.rs @@ -52,7 +52,7 @@ use sp_staking::{ SessionIndex, }; -use super::{Call, Config, Pallet}; +use super::{Call, Config, Pallet, LOG_TARGET}; /// A trait with utility methods for handling equivocation reports in GRANDPA. /// The offence type is generic, and the trait provides , reporting an offence @@ -170,15 +170,9 @@ where }; match SubmitTransaction::>::submit_unsigned_transaction(call.into()) { - Ok(()) => log::info!( - target: "runtime::afg", - "Submitted GRANDPA equivocation report.", - ), - Err(e) => log::error!( - target: "runtime::afg", - "Error submitting equivocation report: {:?}", - e, - ), + Ok(()) => log::info!(target: LOG_TARGET, "Submitted GRANDPA equivocation report.",), + Err(e) => + log::error!(target: LOG_TARGET, "Error submitting equivocation report: {:?}", e,), } Ok(()) @@ -211,7 +205,7 @@ impl Pallet { TransactionSource::Local | TransactionSource::InBlock => { /* allowed */ }, _ => { log::warn!( - target: "runtime::afg", + target: LOG_TARGET, "rejecting unsigned report equivocation transaction because it is not local/in-block." ); diff --git a/frame/grandpa/src/lib.rs b/frame/grandpa/src/lib.rs index fe5b9861853bf..097ce97c7fe47 100644 --- a/frame/grandpa/src/lib.rs +++ b/frame/grandpa/src/lib.rs @@ -70,6 +70,8 @@ pub use equivocation::{ pub use pallet::*; +const LOG_TARGET: &str = "runtime::grandpa"; + #[frame_support::pallet] pub mod pallet { use super::*; diff --git a/frame/grandpa/src/migrations/v4.rs b/frame/grandpa/src/migrations/v4.rs index 81dbd3bab4b67..bb20cb5243f95 100644 --- a/frame/grandpa/src/migrations/v4.rs +++ b/frame/grandpa/src/migrations/v4.rs @@ -34,14 +34,14 @@ pub const OLD_PREFIX: &[u8] = b"GrandpaFinality"; pub fn migrate>(new_pallet_name: N) -> Weight { if new_pallet_name.as_ref().as_bytes() == OLD_PREFIX { log::info!( - target: "runtime::afg", + target: LOG_TARGET, "New pallet name is equal to the old prefix. No migration needs to be done.", ); return Weight::zero() } let storage_version = StorageVersion::get::>(); log::info!( - target: "runtime::afg", + target: LOG_TARGET, "Running migration to v3.1 for grandpa with storage version {:?}", storage_version, ); From 6085dd04ec396dd23c5201dbbae7c3c04a0e2658 Mon Sep 17 00:00:00 2001 From: Davide Galassi Date: Thu, 8 Dec 2022 17:52:53 +0100 Subject: [PATCH 2/3] Fix missing symbol inclusion --- frame/grandpa/src/migrations/v4.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/frame/grandpa/src/migrations/v4.rs b/frame/grandpa/src/migrations/v4.rs index bb20cb5243f95..33e200b728336 100644 --- a/frame/grandpa/src/migrations/v4.rs +++ b/frame/grandpa/src/migrations/v4.rs @@ -15,6 +15,7 @@ // See the License for the specific language governing permissions and // limitations under the License. +use crate::LOG_TARGET; use frame_support::{ traits::{Get, StorageVersion}, weights::Weight, From 0f5232c03959fe1a960c0d5c633be0694bfb2ee4 Mon Sep 17 00:00:00 2001 From: Davide Galassi Date: Mon, 12 Dec 2022 13:58:55 +0100 Subject: [PATCH 3/3] Nit: import-queue to sync::import-queue log target --- client/consensus/common/src/import_queue.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/consensus/common/src/import_queue.rs b/client/consensus/common/src/import_queue.rs index 62fcde019b9f1..d64b029e71e4c 100644 --- a/client/consensus/common/src/import_queue.rs +++ b/client/consensus/common/src/import_queue.rs @@ -45,7 +45,7 @@ use crate::{ pub use basic_queue::BasicQueue; use sp_consensus::{error::Error as ConsensusError, BlockOrigin, CacheKeyId}; -const LOG_TARGET: &str = "import-queue"; +const LOG_TARGET: &str = "sync::import-queue"; /// A commonly-used Import Queue type. ///