From fda202e21888121d7efdd62c535f0d9d4cfc5150 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 14 Dec 2024 13:08:12 +0100 Subject: [PATCH 01/15] tracing for logging in fatxpool --- Cargo.lock | 1 + substrate/client/transaction-pool/Cargo.toml | 1 + .../client/transaction-pool/src/common/mod.rs | 1 + .../src/common/tracing_log_xt.rs | 48 +++++++++++++++++++ .../src/fork_aware_txpool/dropped_watcher.rs | 7 +-- 5 files changed, 55 insertions(+), 3 deletions(-) create mode 100644 substrate/client/transaction-pool/src/common/tracing_log_xt.rs diff --git a/Cargo.lock b/Cargo.lock index 43a7880362b4..0731138fbaea 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -23811,6 +23811,7 @@ dependencies = [ "thiserror", "tokio", "tokio-stream", + "tracing", ] [[package]] diff --git a/substrate/client/transaction-pool/Cargo.toml b/substrate/client/transaction-pool/Cargo.toml index d346add93a64..3b4627dbe027 100644 --- a/substrate/client/transaction-pool/Cargo.toml +++ b/substrate/client/transaction-pool/Cargo.toml @@ -40,6 +40,7 @@ sp-tracing = { workspace = true, default-features = true } sp-transaction-pool = { workspace = true, default-features = true } tokio-stream = { workspace = true } tokio = { workspace = true, default-features = true, features = ["macros", "time"] } +tracing = { workspace = true, default-features = true } [dev-dependencies] array-bytes = { workspace = true, default-features = true } diff --git a/substrate/client/transaction-pool/src/common/mod.rs b/substrate/client/transaction-pool/src/common/mod.rs index fb280e8780ad..66a5ad86b1bf 100644 --- a/substrate/client/transaction-pool/src/common/mod.rs +++ b/substrate/client/transaction-pool/src/common/mod.rs @@ -22,6 +22,7 @@ pub(crate) mod api; pub(crate) mod enactment_state; pub(crate) mod error; pub(crate) mod log_xt; +pub(crate) mod tracing_log_xt; pub(crate) mod metrics; #[cfg(test)] pub(crate) mod tests; diff --git a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs new file mode 100644 index 000000000000..2fb4abc9a7c4 --- /dev/null +++ b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs @@ -0,0 +1,48 @@ +macro_rules! log_xt { + (data: hash, target: $target:expr, $level:expr, $tx_collection:expr, $text_with_format:expr) => { + for tx in $tx_collection { + tracing::event!( + $level, + target = $target, + message = $text_with_format, + tx = format!("{:?}", tx) + ); + } + }; + (data: hash, target: $target:expr, $level:expr, $tx_collection:expr, $text_with_format:expr, $($arg:expr),*) => { + for tx in $tx_collection { + tracing::event!( + $level, + target = $target, + message = $text_with_format, + tx = format!("{:?}", tx), + $($arg),* + ); + } + }; + (data: tuple, target: $target:expr, $level:expr, $tx_collection:expr, $text_with_format:expr) => { + for tx in $tx_collection { + tracing::event!( + $level, + target = $target, + message = $text_with_format, + tx_0 = format!("{:?}", tx.0), + tx_1 = format!("{:?}", tx.1) + ); + } + }; +} +macro_rules! log_xt_trace { + (data: $datatype:ident, target: $target:expr, $($arg:tt)+) => { + $crate::common::tracing_log_xt::log_xt!(data: $datatype, target: $target, tracing::Level::TRACE, $($arg)+); + }; + (target: $target:expr, $tx_collection:expr, $text_with_format:expr) => { + $crate::common::tracing_log_xt::log_xt!(data: hash, target: $target, tracing::Level::TRACE, $tx_collection, $text_with_format); + }; + (target: $target:expr, $tx_collection:expr, $text_with_format:expr, $($arg:expr)*) => { + $crate::common::tracing_log_xt::log_xt!(data: hash, target: $target, tracing::Level::TRACE, $tx_collection, $text_with_format, $($arg)*); + }; +} + +pub(crate) use log_xt; +pub(crate) use log_xt_trace; \ No newline at end of file diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs index 7679e3b169d2..62f1badd5326 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs @@ -22,13 +22,13 @@ //! by any view are detected and properly notified. use crate::{ - common::log_xt::log_xt_trace, + common::tracing_log_xt::log_xt_trace, fork_aware_txpool::stream_map_util::next_event, graph::{self, BlockHash, ExtrinsicHash}, LOG_TARGET, }; use futures::stream::StreamExt; -use log::{debug, trace}; +use tracing::{debug, trace}; use sc_transaction_pool_api::TransactionStatus; use sc_utils::mpsc; use sp_runtime::traits::Block as BlockT; @@ -275,7 +275,8 @@ where return Some(DroppedTransaction::new_enforced_by_limts(tx_hash)) } } else { - debug!("[{:?}] dropped_watcher: removing (non-tracked) tx", tx_hash); + let tx_hash_string = format!("{:?}", tx_hash); + debug!(tx_hash_string, "dropped_watcher: removing (non-tracked) tx" ); return Some(DroppedTransaction::new_enforced_by_limts(tx_hash)) } }, From a85ddb28602ff6ffd9349ee9d74aebdc92d3a298 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 28 Dec 2024 13:03:50 +0100 Subject: [PATCH 02/15] other tracing logs --- .../fork_aware_txpool/fork_aware_txpool.rs | 88 +++++++++---------- .../import_notification_sink.rs | 2 +- .../fork_aware_txpool/multi_view_listener.rs | 32 +++---- .../fork_aware_txpool/revalidation_worker.rs | 8 +- .../src/fork_aware_txpool/tx_mem_pool.rs | 16 ++-- .../src/fork_aware_txpool/view.rs | 30 +++---- .../src/fork_aware_txpool/view_store.rs | 26 +++--- 7 files changed, 101 insertions(+), 101 deletions(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs index 4ec87f1fefa4..2712303e2abc 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs @@ -29,7 +29,7 @@ use super::{ }; use crate::{ api::FullChainApi, - common::log_xt::log_xt_trace, + common::tracing_log_xt::log_xt_trace, enactment_state::{EnactmentAction, EnactmentState}, fork_aware_txpool::{dropped_watcher::DroppedReason, revalidation_worker}, graph::{ @@ -100,10 +100,10 @@ where /// /// `ready_iterator` is a closure that generates the result data to be sent to the pollers. fn trigger(&mut self, at: Block::Hash, ready_iterator: impl Fn() -> T) { - log::trace!(target: LOG_TARGET, "fatp::trigger {at:?} pending keys: {:?}", self.pollers.keys()); + tracing::trace!(target: LOG_TARGET, "fatp::trigger {at:?} pending keys: {:?}", self.pollers.keys()); let Some(pollers) = self.pollers.remove(&at) else { return }; pollers.into_iter().for_each(|p| { - log::debug!(target: LOG_TARGET, "trigger ready signal at block {}", at); + tracing::debug!(target: LOG_TARGET, "trigger ready signal at block {}", at); let _ = p.send(ready_iterator()); }); } @@ -260,11 +260,11 @@ where ) { loop { let Some(dropped) = dropped_stream.next().await else { - log::debug!(target: LOG_TARGET, "fatp::dropped_monitor_task: terminated..."); + tracing::debug!(target: LOG_TARGET, "fatp::dropped_monitor_task: terminated..."); break; }; let dropped_tx_hash = dropped.tx_hash; - log::trace!(target: LOG_TARGET, "[{:?}] fatp::dropped notification {:?}, removing", dropped_tx_hash,dropped.reason); + tracing::trace!(target: LOG_TARGET, "[{:?}] fatp::dropped notification {:?}, removing", dropped_tx_hash,dropped.reason); match dropped.reason { DroppedReason::Usurped(new_tx_hash) => { if let Some(new_tx) = mempool.get_by_hash(new_tx_hash) { @@ -277,7 +277,7 @@ where ) .await; } else { - log::trace!( + tracing::trace!( target:LOG_TARGET, "error: dropped_monitor_task: no entry in mempool for new transaction {:?}", new_tx_hash, @@ -428,7 +428,7 @@ where pub async fn ready_at_light(&self, at: Block::Hash) -> ReadyIteratorFor { let start = Instant::now(); let api = self.api.clone(); - log::trace!(target: LOG_TARGET, "fatp::ready_at_light {:?}", at); + tracing::trace!(target: LOG_TARGET, "fatp::ready_at_light {:?}", at); let Ok(block_number) = self.api.resolve_block_number(at) else { return Box::new(std::iter::empty()) @@ -461,7 +461,7 @@ where .block_body(h.hash) .await .unwrap_or_else(|e| { - log::warn!(target: LOG_TARGET, "Compute ready light transactions: error request: {}", e); + tracing::warn!(target: LOG_TARGET, "Compute ready light transactions: error request: {}", e); None }) .unwrap_or_default() @@ -482,7 +482,7 @@ where let _ = tmp_view.pool.validated_pool().prune_tags(tags); let after_count = tmp_view.pool.validated_pool().status().ready; - log::debug!(target: LOG_TARGET, + tracing::debug!(target: LOG_TARGET, "fatp::ready_at_light {} from {} before: {} to be removed: {} after: {} took:{:?}", at, best_view.at.hash, @@ -494,7 +494,7 @@ where Box::new(tmp_view.pool.validated_pool().ready()) } else { let empty: ReadyIteratorFor = Box::new(std::iter::empty()); - log::debug!(target: LOG_TARGET, "fatp::ready_at_light {} -> empty, took:{:?}", at, start.elapsed()); + tracing::debug!(target: LOG_TARGET, "fatp::ready_at_light {} -> empty, took:{:?}", at, start.elapsed()); empty } } @@ -514,7 +514,7 @@ where at: Block::Hash, timeout: std::time::Duration, ) -> ReadyIteratorFor { - log::debug!(target: LOG_TARGET, "fatp::ready_at_with_timeout at {:?} allowed delay: {:?}", at, timeout); + tracing::debug!(target: LOG_TARGET, "fatp::ready_at_with_timeout at {:?} allowed delay: {:?}", at, timeout); let timeout = futures_timer::Delay::new(timeout); let (view_already_exists, ready_at) = self.ready_at_internal(at); @@ -527,7 +527,7 @@ where select! { ready = ready_at => Some(ready), _ = timeout => { - log::warn!(target: LOG_TARGET, + tracing::warn!(target: LOG_TARGET, "Timeout fired waiting for transaction pool at block: ({:?}). \ Proceeding with production.", at, @@ -550,7 +550,7 @@ where let mut ready_poll = self.ready_poll.lock(); if let Some((view, inactive)) = self.view_store.get_view_at(at, true) { - log::debug!(target: LOG_TARGET, "fatp::ready_at_internal {at:?} (inactive:{inactive:?})"); + tracing::debug!(target: LOG_TARGET, "fatp::ready_at_internal {at:?} (inactive:{inactive:?})"); let iterator: ReadyIteratorFor = Box::new(view.pool.validated_pool().ready()); return (true, async move { iterator }.boxed()); } @@ -559,12 +559,12 @@ where .add(at) .map(|received| { received.unwrap_or_else(|e| { - log::warn!(target: LOG_TARGET, "Error receiving ready-set iterator: {:?}", e); + tracing::warn!(target: LOG_TARGET, "Error receiving ready-set iterator: {:?}", e); Box::new(std::iter::empty()) }) }) .boxed(); - log::debug!(target: LOG_TARGET, + tracing::debug!(target: LOG_TARGET, "fatp::ready_at_internal {at:?} pending keys: {:?}", ready_poll.pollers.keys() ); @@ -644,7 +644,7 @@ where xts: Vec>, ) -> Result, Self::Error>>, Self::Error> { let view_store = self.view_store.clone(); - log::debug!(target: LOG_TARGET, "fatp::submit_at count:{} views:{}", xts.len(), self.active_views_count()); + tracing::debug!(target: LOG_TARGET, "fatp::submit_at count:{} views:{}", xts.len(), self.active_views_count()); log_xt_trace!(target: LOG_TARGET, xts.iter().map(|xt| self.tx_hash(xt)), "[{:?}] fatp::submit_at"); let xts = xts.into_iter().map(Arc::from).collect::>(); let mempool_results = self.mempool.extend_unwatched(source, &xts); @@ -692,7 +692,7 @@ where source: TransactionSource, xt: TransactionFor, ) -> Result, Self::Error> { - log::trace!(target: LOG_TARGET, "[{:?}] fatp::submit_one views:{}", self.tx_hash(&xt), self.active_views_count()); + tracing::trace!(target: LOG_TARGET, "[{:?}] fatp::submit_one views:{}", self.tx_hash(&xt), self.active_views_count()); match self.submit_at(_at, source, vec![xt]).await { Ok(mut v) => v.pop().expect("There is exactly one element in result of submit_at. qed."), @@ -710,7 +710,7 @@ where source: TransactionSource, xt: TransactionFor, ) -> Result>>, Self::Error> { - log::trace!(target: LOG_TARGET, "[{:?}] fatp::submit_and_watch views:{}", self.tx_hash(&xt), self.active_views_count()); + tracing::trace!(target: LOG_TARGET, "[{:?}] fatp::submit_and_watch views:{}", self.tx_hash(&xt), self.active_views_count()); let xt = Arc::from(xt); let InsertionInfo { hash: xt_hash, source: timed_source } = match self.mempool.push_watched(source, xt.clone()) { @@ -733,7 +733,7 @@ where // useful for verification for debugging purposes). fn remove_invalid(&self, hashes: &[TxHash]) -> Vec> { if !hashes.is_empty() { - log::debug!(target: LOG_TARGET, "fatp::remove_invalid {}", hashes.len()); + tracing::debug!(target: LOG_TARGET, "fatp::remove_invalid {}", hashes.len()); log_xt_trace!(target:LOG_TARGET, hashes, "[{:?}] fatp::remove_invalid"); self.metrics .report(|metrics| metrics.removed_invalid_txs.inc_by(hashes.len() as _)); @@ -784,7 +784,7 @@ where let result = most_recent_view .map(|block_hash| self.view_store.ready_transaction(block_hash, tx_hash)) .flatten(); - log::trace!( + tracing::trace!( target: LOG_TARGET, "[{tx_hash:?}] ready_transaction: {} {:?}", result.is_some(), @@ -850,7 +850,7 @@ where _at: Block::Hash, xt: sc_transaction_pool_api::LocalTransactionFor, ) -> Result { - log::debug!(target: LOG_TARGET, "fatp::submit_local views:{}", self.active_views_count()); + tracing::debug!(target: LOG_TARGET, "fatp::submit_local views:{}", self.active_views_count()); let xt = Arc::from(xt); let InsertionInfo { hash: xt_hash, .. } = self .mempool @@ -878,7 +878,7 @@ where let hash_and_number = match tree_route.last() { Some(hash_and_number) => hash_and_number, None => { - log::warn!( + tracing::warn!( target: LOG_TARGET, "Skipping ChainEvent - no last block in tree route {:?}", tree_route, @@ -888,7 +888,7 @@ where }; if self.has_view(&hash_and_number.hash) { - log::trace!( + tracing::trace!( target: LOG_TARGET, "view already exists for block: {:?}", hash_and_number, @@ -926,7 +926,7 @@ where at: &HashAndNumber, tree_route: &TreeRoute, ) -> Option>> { - log::debug!( + tracing::debug!( target: LOG_TARGET, "build_new_view: for: {:?} from: {:?} tree_route: {:?}", at, @@ -940,7 +940,7 @@ where } view } else { - log::debug!(target: LOG_TARGET, "creating non-cloned view: for: {at:?}"); + tracing::debug!(target: LOG_TARGET, "creating non-cloned view: for: {at:?}"); View::new( self.api.clone(), at.clone(), @@ -968,20 +968,20 @@ where // sync the transactions statuses and referencing views in all the listeners with newly // cloned view. view.pool.validated_pool().retrigger_notifications(); - log::debug!(target: LOG_TARGET, "register_listeners: at {at:?} took {duration:?}"); + tracing::debug!(target: LOG_TARGET, "register_listeners: at {at:?} took {duration:?}"); // 2. Handle transactions from the tree route. Pruning transactions from the view first // will make some space for mempool transactions in case we are at the view's limits. let start = Instant::now(); self.update_view_with_fork(&view, tree_route, at.clone()).await; let duration = start.elapsed(); - log::debug!(target: LOG_TARGET, "update_view_with_fork: at {at:?} took {duration:?}"); + tracing::debug!(target: LOG_TARGET, "update_view_with_fork: at {at:?} took {duration:?}"); // 3. Finally, submit transactions from the mempool. let start = Instant::now(); self.update_view_with_mempool(&mut view, watched_xts).await; let duration = start.elapsed(); - log::debug!(target: LOG_TARGET, "update_view_with_mempool: at {at:?} took {duration:?}"); + tracing::debug!(target: LOG_TARGET, "update_view_with_mempool: at {at:?} took {duration:?}"); let view = Arc::from(view); self.view_store.insert_new_view(view.clone(), tree_route).await; @@ -1006,7 +1006,7 @@ where api.block_body(h.hash) .await .unwrap_or_else(|e| { - log::warn!(target: LOG_TARGET, "Compute ready light transactions: error request: {}", e); + tracing::warn!(target: LOG_TARGET, "Compute ready light transactions: error request: {}", e); None }) .unwrap_or_default() @@ -1017,7 +1017,7 @@ where }); } - log::debug!(target: LOG_TARGET, + tracing::debug!(target: LOG_TARGET, "fatp::extrinsics_included_since_finalized {} from {} count: {} took:{:?}", at, recent_finalized_block, @@ -1037,7 +1037,7 @@ where &self, view: &View, ) -> Vec<(ExtrinsicHash, Arc>)> { - log::debug!( + tracing::debug!( target: LOG_TARGET, "register_listeners: {:?} xts:{:?} v:{}", view.at, @@ -1055,7 +1055,7 @@ where let watcher = view.create_watcher(tx_hash); let at = view.at.clone(); async move { - log::trace!(target: LOG_TARGET, "[{:?}] adding watcher {:?}", tx_hash, at.hash); + tracing::trace!(target: LOG_TARGET, "[{:?}] adding watcher {:?}", tx_hash, at.hash); self.view_store.listener.add_view_watcher_for_tx( tx_hash, at.hash, @@ -1087,7 +1087,7 @@ where view: &View, watched_xts: Vec<(ExtrinsicHash, Arc>)>, ) { - log::debug!( + tracing::debug!( target: LOG_TARGET, "update_view_with_mempool: {:?} xts:{:?} v:{}", view.at, @@ -1114,7 +1114,7 @@ where let submitted_count = watched_results.len(); - log::debug!( + tracing::debug!( target: LOG_TARGET, "update_view_with_mempool: at {:?} submitted {}/{}", view.at.hash, @@ -1147,7 +1147,7 @@ where tree_route: &TreeRoute, hash_and_number: HashAndNumber, ) { - log::debug!(target: LOG_TARGET, "update_view_with_fork tree_route: {:?} {tree_route:?}", view.at); + tracing::debug!(target: LOG_TARGET, "update_view_with_fork tree_route: {:?} {tree_route:?}", view.at); let api = self.api.clone(); // We keep track of everything we prune so that later we won't add @@ -1177,7 +1177,7 @@ where .block_body(hash) .await .unwrap_or_else(|e| { - log::warn!(target: LOG_TARGET, "Failed to fetch block body: {}", e); + tracing::warn!(target: LOG_TARGET, "Failed to fetch block body: {}", e); None }) .unwrap_or_default() @@ -1196,7 +1196,7 @@ where resubmitted_to_report += 1; if !contains { - log::trace!( + tracing::trace!( target: LOG_TARGET, "[{:?}]: Resubmitting from retracted block {:?}", tx_hash, @@ -1234,7 +1234,7 @@ where /// - purging finalized transactions from the mempool and triggering mempool revalidation, async fn handle_finalized(&self, finalized_hash: Block::Hash, tree_route: &[Block::Hash]) { let finalized_number = self.api.block_id_to_number(&BlockId::Hash(finalized_hash)); - log::debug!(target: LOG_TARGET, "handle_finalized {finalized_number:?} tree_route: {tree_route:?} views_count:{}", self.active_views_count()); + tracing::debug!(target: LOG_TARGET, "handle_finalized {finalized_number:?} tree_route: {tree_route:?} views_count:{}", self.active_views_count()); let finalized_xts = self.view_store.handle_finalized(finalized_hash, tree_route).await; @@ -1252,11 +1252,11 @@ where ) .await; } else { - log::trace!(target: LOG_TARGET, "purge_transactions_later skipped, cannot find block number {finalized_number:?}"); + tracing::trace!(target: LOG_TARGET, "purge_transactions_later skipped, cannot find block number {finalized_number:?}"); } self.ready_poll.lock().remove_cancelled(); - log::trace!(target: LOG_TARGET, "handle_finalized after views_count:{:?}", self.active_views_count()); + tracing::trace!(target: LOG_TARGET, "handle_finalized after views_count:{:?}", self.active_views_count()); } /// Computes a hash of the provided transaction @@ -1275,7 +1275,7 @@ where /// Executes the maintainance for the given chain event. async fn maintain(&self, event: ChainEvent) { let start = Instant::now(); - log::debug!(target: LOG_TARGET, "processing event: {event:?}"); + tracing::debug!(target: LOG_TARGET, "processing event: {event:?}"); self.view_store.finish_background_revalidations().await; @@ -1300,7 +1300,7 @@ where match result { Err(msg) => { - log::trace!(target: LOG_TARGET, "enactment_state::update error: {msg}"); + tracing::trace!(target: LOG_TARGET, "enactment_state::update error: {msg}"); self.enactment_state.lock().force_update(&event); }, Ok(EnactmentAction::Skip) => return, @@ -1326,7 +1326,7 @@ where ChainEvent::Finalized { hash, ref tree_route } => { self.handle_finalized(hash, tree_route).await; - log::trace!( + tracing::trace!( target: LOG_TARGET, "on-finalized enacted: {tree_route:?}, previously finalized: \ {prev_finalized_block:?}", @@ -1336,7 +1336,7 @@ where let maintain_duration = start.elapsed(); - log::info!( + tracing::info!( target: LOG_TARGET, "maintain: txs:{:?} views:[{};{:?}] event:{event:?} took:{:?}", self.mempool_len(), diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs index f9a41673bb8f..2be702e51790 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs @@ -27,7 +27,7 @@ use futures::{ stream::StreamExt, Future, FutureExt, }; -use log::trace; +use tracing::trace; use parking_lot::RwLock; use sc_utils::mpsc; use std::{ diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs index a00234a99808..60424e71c3a9 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs @@ -26,7 +26,7 @@ use crate::{ LOG_TARGET, }; use futures::StreamExt; -use log::{debug, trace}; +use tracing::{debug, trace}; use sc_transaction_pool_api::{TransactionStatus, TransactionStatusStream, TxIndex}; use sc_utils::mpsc; use sp_runtime::traits::Block as BlockT; @@ -323,12 +323,12 @@ where biased; Some((view_hash, status)) = next_event(&mut ctx.status_stream_map) => { if let Some(new_status) = ctx.handle(status, view_hash) { - log::trace!(target: LOG_TARGET, "[{:?}] mvl sending out: {new_status:?}", ctx.tx_hash); + trace!(target: LOG_TARGET, "[{:?}] mvl sending out: {new_status:?}", ctx.tx_hash); return Some((new_status, ctx)) } }, cmd = ctx.command_receiver.next() => { - log::trace!(target: LOG_TARGET, "[{:?}] select::rx views:{:?}", + trace!(target: LOG_TARGET, "[{:?}] select::rx views:{:?}", ctx.tx_hash, ctx.status_stream_map.keys().collect::>() ); @@ -341,26 +341,26 @@ where }, ControllerCommand::TransactionInvalidated => { if ctx.handle_invalidate_transaction() { - log::trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Invalid", ctx.tx_hash); + trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Invalid", ctx.tx_hash); return Some((TransactionStatus::Invalid, ctx)) } }, ControllerCommand::FinalizeTransaction(block, index) => { - log::trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Finalized", ctx.tx_hash); + trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Finalized", ctx.tx_hash); ctx.terminate = true; return Some((TransactionStatus::Finalized((block, index)), ctx)) }, ControllerCommand::TransactionBroadcasted(peers) => { - log::trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Broadcasted", ctx.tx_hash); + trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Broadcasted", ctx.tx_hash); return Some((TransactionStatus::Broadcast(peers), ctx)) }, ControllerCommand::TransactionDropped(DroppedReason::LimitsEnforced) => { - log::trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Dropped", ctx.tx_hash); + trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Dropped", ctx.tx_hash); ctx.terminate = true; return Some((TransactionStatus::Dropped, ctx)) }, ControllerCommand::TransactionDropped(DroppedReason::Usurped(by)) => { - log::trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Usurped({:?})", ctx.tx_hash, by); + trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Usurped({:?})", ctx.tx_hash, by); ctx.terminate = true; return Some((TransactionStatus::Usurped(by), ctx)) }, @@ -405,7 +405,7 @@ where sender .unbounded_send(ControllerCommand::RemoveViewStream(block_hash)) .map_err(|e| { - log::trace!(target: LOG_TARGET, "[{:?}] remove_view: send message failed: {:?}", tx_hash, e); + trace!(target: LOG_TARGET, "[{:?}] remove_view: send message failed: {:?}", tx_hash, e); e }) .is_ok() @@ -525,7 +525,7 @@ mod tests { let out = handle.await.unwrap(); assert_eq!(out, events); - log::debug!("out: {:#?}", out); + debug!("out: {:#?}", out); } #[tokio::test] @@ -560,7 +560,7 @@ mod tests { let out = handle.await.unwrap(); - log::debug!("out: {:#?}", out); + debug!("out: {:#?}", out); assert!(out.iter().all(|v| vec![ TransactionStatus::Future, TransactionStatus::Ready, @@ -600,7 +600,7 @@ mod tests { listener.invalidate_transactions(&[tx_hash]); let out = handle.await.unwrap(); - log::debug!("out: {:#?}", out); + debug!("out: {:#?}", out); assert!(out.iter().all(|v| vec![ TransactionStatus::Future, TransactionStatus::Ready, @@ -654,8 +654,8 @@ mod tests { let out_tx0 = handle0.await.unwrap(); let out_tx1 = handle1.await.unwrap(); - log::debug!("out_tx0: {:#?}", out_tx0); - log::debug!("out_tx1: {:#?}", out_tx1); + debug!("out_tx0: {:#?}", out_tx0); + debug!("out_tx1: {:#?}", out_tx1); assert!(out_tx0.iter().all(|v| vec![ TransactionStatus::Future, TransactionStatus::Ready, @@ -707,7 +707,7 @@ mod tests { listener.invalidate_transactions(&[tx_hash]); let out = handle.await.unwrap(); - log::debug!("out: {:#?}", out); + debug!("out: {:#?}", out); // invalid shall not be sent assert!(out.iter().all(|v| vec![ @@ -740,7 +740,7 @@ mod tests { listener.add_view_watcher_for_tx(tx_hash, block_hash0, view_stream0.boxed()); let out = handle.await.unwrap(); - log::debug!("out: {:#?}", out); + debug!("out: {:#?}", out); assert!(out.iter().all(|v| vec![TransactionStatus::Invalid].contains(v))); assert_eq!(out.len(), 1); diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs index e1c65a08a70b..4b9615654271 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs @@ -131,7 +131,7 @@ where view: Arc>, finish_revalidation_worker_channels: FinishRevalidationWorkerChannels, ) { - log::trace!( + tracing::trace!( target: LOG_TARGET, "revalidation_queue::revalidate_view: Sending view to revalidation queue at {}", view.at.hash @@ -142,7 +142,7 @@ where view, finish_revalidation_worker_channels, )) { - log::warn!(target: LOG_TARGET, "revalidation_queue::revalidate_view: Failed to update background worker: {:?}", e); + tracing::warn!(target: LOG_TARGET, "revalidation_queue::revalidate_view: Failed to update background worker: {:?}", e); } } else { view.revalidate(finish_revalidation_worker_channels).await @@ -161,7 +161,7 @@ where mempool: Arc>, finalized_hash: HashAndNumber, ) { - log::trace!( + tracing::trace!( target: LOG_TARGET, "Sent mempool to revalidation queue at hash: {:?}", finalized_hash @@ -171,7 +171,7 @@ where if let Err(e) = to_worker.unbounded_send(WorkerPayload::RevalidateMempool(mempool, finalized_hash)) { - log::warn!(target: LOG_TARGET, "Failed to update background worker: {:?}", e); + tracing::warn!(target: LOG_TARGET, "Failed to update background worker: {:?}", e); } } else { mempool.revalidate(finalized_hash).await diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs index 989ae4425dc4..ad6c7932b4a5 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs @@ -28,7 +28,7 @@ use super::{metrics::MetricsLink as PrometheusMetrics, multi_view_listener::MultiViewListener}; use crate::{ - common::log_xt::log_xt_trace, + common::tracing_log_xt::log_xt_trace, graph, graph::{base_pool::TimedTransactionSource, tracked_map::Size, ExtrinsicFor, ExtrinsicHash}, LOG_TARGET, @@ -295,7 +295,7 @@ where Err(sc_transaction_pool_api::error::Error::AlreadyImported(Box::new(hash)).into()), (false, _) => Err(sc_transaction_pool_api::error::Error::ImmediatelyDropped.into()), }; - log::trace!(target: LOG_TARGET, "[{:?}] mempool::try_insert: {:?}", hash, result.as_ref().map(|r| r.hash)); + tracing::trace!(target: LOG_TARGET, "[{:?}] mempool::try_insert: {:?}", hash, result.as_ref().map(|r| r.hash)); result } @@ -335,7 +335,7 @@ where &self, dropped: &ExtrinsicHash, ) -> Option>> { - log::debug!(target: LOG_TARGET, "[{:?}] mempool::remove_dropped_transaction", dropped); + tracing::debug!(target: LOG_TARGET, "[{:?}] mempool::remove_dropped_transaction", dropped); self.transactions.write().remove(dropped) } @@ -371,7 +371,7 @@ where /// /// Returns a vector of invalid transaction hashes. async fn revalidate_inner(&self, finalized_block: HashAndNumber) -> Vec { - log::trace!(target: LOG_TARGET, "mempool::revalidate at:{finalized_block:?}"); + tracing::trace!(target: LOG_TARGET, "mempool::revalidate at:{finalized_block:?}"); let start = Instant::now(); let (count, input) = { @@ -414,7 +414,7 @@ where Err(_) | Ok(Err(TransactionValidityError::Unknown(_))) | Ok(Err(TransactionValidityError::Invalid(_))) => { - log::trace!( + tracing::trace!( target: LOG_TARGET, "[{:?}]: Purging: invalid: {:?}", xt_hash, @@ -425,7 +425,7 @@ where }) .collect::>(); - log::debug!( + tracing::debug!( target: LOG_TARGET, "mempool::revalidate: at {finalized_block:?} count:{input_len}/{count} invalid_hashes:{} took {duration:?}", invalid_hashes.len(), ); @@ -438,7 +438,7 @@ where &self, finalized_xts: &Vec>, ) { - log::debug!(target: LOG_TARGET, "purge_finalized_transactions count:{:?}", finalized_xts.len()); + tracing::debug!(target: LOG_TARGET, "purge_finalized_transactions count:{:?}", finalized_xts.len()); log_xt_trace!(target: LOG_TARGET, finalized_xts, "[{:?}] purged finalized transactions"); let mut transactions = self.transactions.write(); finalized_xts.iter().for_each(|t| { @@ -449,7 +449,7 @@ where /// Revalidates transactions in the memory pool against a given finalized block and removes /// invalid ones. pub(super) async fn revalidate(&self, finalized_block: HashAndNumber) { - log::trace!(target: LOG_TARGET, "purge_transactions at:{:?}", finalized_block); + tracing::trace!(target: LOG_TARGET, "purge_transactions at:{:?}", finalized_block); let invalid_hashes = self.revalidate_inner(finalized_block.clone()).await; self.metrics.report(|metrics| { diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index 3cbb8fa4871d..1493688a7fd8 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -159,7 +159,7 @@ where &self, xts: impl IntoIterator)>, ) -> Vec, ChainApi::Error>> { - if log::log_enabled!(target: LOG_TARGET, log::Level::Trace) { + if tracing::enabled!(target: LOG_TARGET, tracing::Level::TRACE) { let xts = xts.into_iter().collect::>(); log_xt_trace!(target: LOG_TARGET, xts.iter().map(|(_,xt)| self.pool.validated_pool().api().hash_and_length(xt).0), "[{:?}] view::submit_many at:{}", self.at.hash); self.pool.submit_at(&self.at, xts).await @@ -174,7 +174,7 @@ where source: TimedTransactionSource, xt: ExtrinsicFor, ) -> Result, ExtrinsicHash>, ChainApi::Error> { - log::trace!(target: LOG_TARGET, "[{:?}] view::submit_and_watch at:{}", self.pool.validated_pool().api().hash_and_length(&xt).0, self.at.hash); + tracing::trace!(target: LOG_TARGET, "[{:?}] view::submit_and_watch at:{}", self.pool.validated_pool().api().hash_and_length(&xt).0, self.at.hash); self.pool.submit_and_watch(&self.at, source, xt).await } @@ -184,7 +184,7 @@ where xt: ExtrinsicFor, ) -> Result, ChainApi::Error> { let (hash, length) = self.pool.validated_pool().api().hash_and_length(&xt); - log::trace!(target: LOG_TARGET, "[{:?}] view::submit_local at:{}", hash, self.at.hash); + tracing::trace!(target: LOG_TARGET, "[{:?}] view::submit_local at:{}", hash, self.at.hash); let validity = self .pool @@ -258,7 +258,7 @@ where revalidation_result_tx, } = finish_revalidation_worker_channels; - log::trace!(target:LOG_TARGET, "view::revalidate: at {} starting", self.at.hash); + tracing::trace!(target:LOG_TARGET, "view::revalidate: at {} starting", self.at.hash); let start = Instant::now(); let validated_pool = self.pool.validated_pool(); let api = validated_pool.api(); @@ -279,7 +279,7 @@ where let mut should_break = false; tokio::select! { _ = finish_revalidation_request_rx.recv() => { - log::trace!(target: LOG_TARGET, "view::revalidate: finish revalidation request received at {}.", self.at.hash); + tracing::trace!(target: LOG_TARGET, "view::revalidate: finish revalidation request received at {}.", self.at.hash); break } _ = async { @@ -302,7 +302,7 @@ where self.metrics.report(|metrics| { metrics.view_revalidation_duration.observe(revalidation_duration.as_secs_f64()); }); - log::debug!( + tracing::debug!( target:LOG_TARGET, "view::revalidate: at {:?} count: {}/{} took {:?}", self.at.hash, @@ -331,7 +331,7 @@ where ); }, Ok(Err(TransactionValidityError::Unknown(e))) => { - log::trace!( + tracing::trace!( target: LOG_TARGET, "[{:?}]: Removing. Cannot determine transaction validity: {:?}", tx_hash, @@ -340,7 +340,7 @@ where invalid_hashes.push(tx_hash); }, Err(validation_err) => { - log::trace!( + tracing::trace!( target: LOG_TARGET, "[{:?}]: Removing due to error during revalidation: {}", tx_hash, @@ -351,12 +351,12 @@ where } } - log::trace!(target:LOG_TARGET, "view::revalidate: sending revalidation result at {}", self.at.hash); + tracing::trace!(target:LOG_TARGET, "view::revalidate: sending revalidation result at {}", self.at.hash); if let Err(e) = revalidation_result_tx .send(RevalidationResult { invalid_hashes, revalidated }) .await { - log::trace!(target:LOG_TARGET, "view::revalidate: sending revalidation_result at {} failed {:?}", self.at.hash, e); + tracing::trace!(target:LOG_TARGET, "view::revalidate: sending revalidation_result at {} failed {:?}", self.at.hash, e); } } @@ -374,7 +374,7 @@ where super::revalidation_worker::RevalidationQueue, >, ) { - log::trace!(target:LOG_TARGET,"view::start_background_revalidation: at {}", view.at.hash); + tracing::trace!(target:LOG_TARGET,"view::start_background_revalidation: at {}", view.at.hash); let (finish_revalidation_request_tx, finish_revalidation_request_rx) = tokio::sync::mpsc::channel(1); let (revalidation_result_tx, revalidation_result_rx) = tokio::sync::mpsc::channel(1); @@ -404,10 +404,10 @@ where /// /// Refer to [*View revalidation*](../index.html#view-revalidation) for more details. pub(super) async fn finish_revalidation(&self) { - log::trace!(target:LOG_TARGET,"view::finish_revalidation: at {}", self.at.hash); + tracing::trace!(target:LOG_TARGET,"view::finish_revalidation: at {}", self.at.hash); let Some(revalidation_worker_channels) = self.revalidation_worker_channels.lock().take() else { - log::trace!(target:LOG_TARGET, "view::finish_revalidation: no finish_revalidation_request_tx"); + tracing::trace!(target:LOG_TARGET, "view::finish_revalidation: no finish_revalidation_request_tx"); return }; @@ -418,7 +418,7 @@ where if let Some(finish_revalidation_request_tx) = finish_revalidation_request_tx { if let Err(e) = finish_revalidation_request_tx.send(()).await { - log::trace!(target:LOG_TARGET, "view::finish_revalidation: sending cancellation request at {} failed {:?}", self.at.hash, e); + tracing::trace!(target:LOG_TARGET, "view::finish_revalidation: sending cancellation request at {} failed {:?}", self.at.hash, e); } } @@ -444,7 +444,7 @@ where ); }); - log::debug!( + tracing::debug!( target:LOG_TARGET, "view::finish_revalidation: applying revalidation result invalid: {} revalidated: {} at {:?} took {:?}", revalidation_result.invalid_hashes.len(), diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs index a06c051f0a7e..a3fbde87c983 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs @@ -169,7 +169,7 @@ where .find_or_first(Result::is_ok); if let Some(Err(err)) = result { - log::trace!(target: LOG_TARGET, "[{:?}] submit_local: err: {}", tx_hash, err); + tracing::trace!(target: LOG_TARGET, "[{:?}] submit_local: err: {}", tx_hash, err); return Err(err) }; @@ -223,7 +223,7 @@ where .find_or_first(Result::is_ok); if let Some(Err(err)) = maybe_error { - log::trace!(target: LOG_TARGET, "[{:?}] submit_and_watch: err: {}", tx_hash, err); + tracing::trace!(target: LOG_TARGET, "[{:?}] submit_and_watch: err: {}", tx_hash, err); return Err(err); }; @@ -328,7 +328,7 @@ where finalized_hash: Block::Hash, tree_route: &[Block::Hash], ) -> Vec> { - log::trace!(target: LOG_TARGET, "finalize_route finalized_hash:{finalized_hash:?} tree_route: {tree_route:?}"); + tracing::trace!(target: LOG_TARGET, "finalize_route finalized_hash:{finalized_hash:?} tree_route: {tree_route:?}"); let mut finalized_transactions = Vec::new(); @@ -338,7 +338,7 @@ where .block_body(*block) .await .unwrap_or_else(|e| { - log::warn!(target: LOG_TARGET, "Finalize route: error request: {}", e); + tracing::warn!(target: LOG_TARGET, "Finalize route: error request: {}", e); None }) .unwrap_or_default() @@ -406,7 +406,7 @@ where active_views.insert(view.at.hash, view.clone()); most_recent_view_lock.replace(view.at.hash); }; - log::trace!(target:LOG_TARGET,"insert_new_view: inactive_views: {:?}", self.inactive_views.read().keys()); + tracing::trace!(target:LOG_TARGET,"insert_new_view: inactive_views: {:?}", self.inactive_views.read().keys()); } /// Returns an optional reference to the view at given hash. @@ -463,7 +463,7 @@ where .for_each(drop); } - log::trace!(target:LOG_TARGET,"handle_pre_finalized: removed_views: {:?}", removed_views); + tracing::trace!(target:LOG_TARGET,"handle_pre_finalized: removed_views: {:?}", removed_views); removed_views.iter().for_each(|view| { self.dropped_stream_controller.remove_view(*view); @@ -519,10 +519,10 @@ where retain }); - log::trace!(target:LOG_TARGET,"handle_finalized: inactive_views: {:?}", inactive_views.keys()); + tracing::trace!(target:LOG_TARGET,"handle_finalized: inactive_views: {:?}", inactive_views.keys()); } - log::trace!(target:LOG_TARGET,"handle_finalized: dropped_views: {:?}", dropped_views); + tracing::trace!(target:LOG_TARGET,"handle_finalized: dropped_views: {:?}", dropped_views); self.listener.remove_stale_controllers(); self.dropped_stream_controller.remove_finalized_txs(finalized_xts.clone()); @@ -553,7 +553,7 @@ where .collect::>() }; futures::future::join_all(finish_revalidation_futures).await; - log::trace!(target:LOG_TARGET,"finish_background_revalidations took {:?}", start.elapsed()); + tracing::trace!(target:LOG_TARGET,"finish_background_revalidations took {:?}", start.elapsed()); } /// Replaces an existing transaction in the view_store with a new one. @@ -582,7 +582,7 @@ where }; let xt_hash = self.api.hash_and_length(&xt).0; - log::trace!(target:LOG_TARGET,"[{replaced:?}] replace_transaction wtih {xt_hash:?}, w:{watched}"); + tracing::trace!(target:LOG_TARGET,"[{replaced:?}] replace_transaction wtih {xt_hash:?}, w:{watched}"); self.replace_transaction_in_views(source, xt, xt_hash, replaced, watched).await; @@ -631,7 +631,7 @@ where ); }, Err(e) => { - log::trace!( + tracing::trace!( target:LOG_TARGET, "[{:?}] replace_transaction: submit_and_watch to {} failed {}", xt_hash, view.at.hash, e @@ -640,7 +640,7 @@ where } } else { if let Some(Err(e)) = view.submit_many(std::iter::once((source, xt))).await.pop() { - log::trace!( + tracing::trace!( target:LOG_TARGET, "[{:?}] replace_transaction: submit to {} failed {}", xt_hash, view.at.hash, e @@ -662,7 +662,7 @@ where watched: bool, ) { if watched && !self.listener.contains_tx(&xt_hash) { - log::trace!( + tracing::trace!( target:LOG_TARGET, "error: replace_transaction_in_views: no listener for watched transaction {:?}", xt_hash, From b203a78f4533782b6c5a6f85d540f6b7a3b90665 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 28 Dec 2024 13:05:35 +0100 Subject: [PATCH 03/15] fmt --- substrate/client/transaction-pool/src/common/mod.rs | 2 +- .../client/transaction-pool/src/common/tracing_log_xt.rs | 2 +- .../transaction-pool/src/fork_aware_txpool/dropped_watcher.rs | 4 ++-- .../src/fork_aware_txpool/import_notification_sink.rs | 2 +- .../src/fork_aware_txpool/multi_view_listener.rs | 2 +- 5 files changed, 6 insertions(+), 6 deletions(-) diff --git a/substrate/client/transaction-pool/src/common/mod.rs b/substrate/client/transaction-pool/src/common/mod.rs index 66a5ad86b1bf..446a5c2ec022 100644 --- a/substrate/client/transaction-pool/src/common/mod.rs +++ b/substrate/client/transaction-pool/src/common/mod.rs @@ -22,10 +22,10 @@ pub(crate) mod api; pub(crate) mod enactment_state; pub(crate) mod error; pub(crate) mod log_xt; -pub(crate) mod tracing_log_xt; pub(crate) mod metrics; #[cfg(test)] pub(crate) mod tests; +pub(crate) mod tracing_log_xt; use futures::StreamExt; use std::sync::Arc; diff --git a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs index 2fb4abc9a7c4..b80f049f1b22 100644 --- a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs +++ b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs @@ -45,4 +45,4 @@ macro_rules! log_xt_trace { } pub(crate) use log_xt; -pub(crate) use log_xt_trace; \ No newline at end of file +pub(crate) use log_xt_trace; diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs index 62f1badd5326..c5a281b7fdbb 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs @@ -28,7 +28,6 @@ use crate::{ LOG_TARGET, }; use futures::stream::StreamExt; -use tracing::{debug, trace}; use sc_transaction_pool_api::TransactionStatus; use sc_utils::mpsc; use sp_runtime::traits::Block as BlockT; @@ -41,6 +40,7 @@ use std::{ pin::Pin, }; use tokio_stream::StreamMap; +use tracing::{debug, trace}; /// Represents a transaction that was removed from the transaction pool, including the reason of its /// removal. @@ -276,7 +276,7 @@ where } } else { let tx_hash_string = format!("{:?}", tx_hash); - debug!(tx_hash_string, "dropped_watcher: removing (non-tracked) tx" ); + debug!(tx_hash_string, "dropped_watcher: removing (non-tracked) tx"); return Some(DroppedTransaction::new_enforced_by_limts(tx_hash)) } }, diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs index 2be702e51790..9e65955f53e9 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs @@ -27,7 +27,6 @@ use futures::{ stream::StreamExt, Future, FutureExt, }; -use tracing::trace; use parking_lot::RwLock; use sc_utils::mpsc; use std::{ @@ -38,6 +37,7 @@ use std::{ sync::Arc, }; use tokio_stream::StreamMap; +use tracing::trace; /// A type alias for a pinned, boxed stream of items of type `I`. /// This alias is particularly useful for defining the types of the incoming streams from various diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs index 60424e71c3a9..7bfbf3a6ca5b 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs @@ -26,7 +26,6 @@ use crate::{ LOG_TARGET, }; use futures::StreamExt; -use tracing::{debug, trace}; use sc_transaction_pool_api::{TransactionStatus, TransactionStatusStream, TxIndex}; use sc_utils::mpsc; use sp_runtime::traits::Block as BlockT; @@ -35,6 +34,7 @@ use std::{ pin::Pin, }; use tokio_stream::StreamMap; +use tracing::{debug, trace}; use super::dropped_watcher::{DroppedReason, DroppedTransaction}; From e33fdf2235076047f53faf4eebfaed91176e18ae Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 28 Dec 2024 13:15:30 +0100 Subject: [PATCH 04/15] pr doc --- prdoc/pr_6897.prdoc | 7 +++++++ 1 file changed, 7 insertions(+) create mode 100644 prdoc/pr_6897.prdoc diff --git a/prdoc/pr_6897.prdoc b/prdoc/pr_6897.prdoc new file mode 100644 index 000000000000..38fd9417f48a --- /dev/null +++ b/prdoc/pr_6897.prdoc @@ -0,0 +1,7 @@ +title: 'Tracing Log for fork-aware transaction pool' +doc: +- audience: Node Dev + description: Replacement of log crate with tracing crate for better logging. +crates: +- name: sc-transaction-pool + bump: minor \ No newline at end of file From 4714ac69983f3afea287d3ac8b41cdd1c41e0045 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 4 Jan 2025 10:27:00 +0100 Subject: [PATCH 05/15] use structured logging --- .../src/fork_aware_txpool/dropped_watcher.rs | 3 +- .../fork_aware_txpool/fork_aware_txpool.rs | 296 ++++++++++++------ .../import_notification_sink.rs | 57 ++-- .../fork_aware_txpool/multi_view_listener.rs | 166 ++++++++-- .../fork_aware_txpool/revalidation_worker.rs | 20 +- .../src/fork_aware_txpool/tx_mem_pool.rs | 45 ++- .../src/fork_aware_txpool/view.rs | 121 ++++--- .../src/fork_aware_txpool/view_store.rs | 89 ++++-- 8 files changed, 580 insertions(+), 217 deletions(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs index c5a281b7fdbb..589ab275eb24 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs @@ -275,8 +275,7 @@ where return Some(DroppedTransaction::new_enforced_by_limts(tx_hash)) } } else { - let tx_hash_string = format!("{:?}", tx_hash); - debug!(tx_hash_string, "dropped_watcher: removing (non-tracked) tx"); + debug!(target: LOG_TARGET, ?tx_hash, "dropped_watcher: removing (non-tracked) tx"); return Some(DroppedTransaction::new_enforced_by_limts(tx_hash)) } }, diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs index 2712303e2abc..979b8fa70fa4 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs @@ -100,7 +100,7 @@ where /// /// `ready_iterator` is a closure that generates the result data to be sent to the pollers. fn trigger(&mut self, at: Block::Hash, ready_iterator: impl Fn() -> T) { - tracing::trace!(target: LOG_TARGET, "fatp::trigger {at:?} pending keys: {:?}", self.pollers.keys()); + tracing::trace!(target: LOG_TARGET, ?at, keys = ?self.pollers.keys(), "fatp::trigger"); let Some(pollers) = self.pollers.remove(&at) else { return }; pollers.into_iter().for_each(|p| { tracing::debug!(target: LOG_TARGET, "trigger ready signal at block {}", at); @@ -264,7 +264,12 @@ where break; }; let dropped_tx_hash = dropped.tx_hash; - tracing::trace!(target: LOG_TARGET, "[{:?}] fatp::dropped notification {:?}, removing", dropped_tx_hash,dropped.reason); + tracing::trace!( + target: LOG_TARGET, + ?dropped_tx_hash, + reason = ?dropped.reason, + "fatp::dropped notification, removing" + ); match dropped.reason { DroppedReason::Usurped(new_tx_hash) => { if let Some(new_tx) = mempool.get_by_hash(new_tx_hash) { @@ -278,9 +283,9 @@ where .await; } else { tracing::trace!( - target:LOG_TARGET, - "error: dropped_monitor_task: no entry in mempool for new transaction {:?}", - new_tx_hash, + target: LOG_TARGET, + tx_hash = ?new_tx_hash, + "error: dropped_monitor_task: no entry in mempool for new transaction" ); } }, @@ -428,7 +433,11 @@ where pub async fn ready_at_light(&self, at: Block::Hash) -> ReadyIteratorFor { let start = Instant::now(); let api = self.api.clone(); - tracing::trace!(target: LOG_TARGET, "fatp::ready_at_light {:?}", at); + tracing::trace!( + target: LOG_TARGET, + at = ?at, + "fatp::ready_at_light" + ); let Ok(block_number) = self.api.resolve_block_number(at) else { return Box::new(std::iter::empty()) @@ -461,7 +470,11 @@ where .block_body(h.hash) .await .unwrap_or_else(|e| { - tracing::warn!(target: LOG_TARGET, "Compute ready light transactions: error request: {}", e); + tracing::warn!( + target: LOG_TARGET, + error = %e, + "Compute ready light transactions: error request" + ); None }) .unwrap_or_default() @@ -482,19 +495,25 @@ where let _ = tmp_view.pool.validated_pool().prune_tags(tags); let after_count = tmp_view.pool.validated_pool().status().ready; - tracing::debug!(target: LOG_TARGET, - "fatp::ready_at_light {} from {} before: {} to be removed: {} after: {} took:{:?}", - at, - best_view.at.hash, - before_count, - all_extrinsics.len(), - after_count, - start.elapsed() + tracing::debug!( + target: LOG_TARGET, + at = ?at, + best_view_hash = ?best_view.at.hash, + before_count = before_count, + to_be_removed = all_extrinsics.len(), + after_count = after_count, + took = ?start.elapsed(), + "fatp::ready_at_light" ); Box::new(tmp_view.pool.validated_pool().ready()) } else { let empty: ReadyIteratorFor = Box::new(std::iter::empty()); - tracing::debug!(target: LOG_TARGET, "fatp::ready_at_light {} -> empty, took:{:?}", at, start.elapsed()); + tracing::debug!( + target: LOG_TARGET, + at = ?at, + took = ?start.elapsed(), + "fatp::ready_at_light -> empty" + ); empty } } @@ -514,8 +533,12 @@ where at: Block::Hash, timeout: std::time::Duration, ) -> ReadyIteratorFor { - tracing::debug!(target: LOG_TARGET, "fatp::ready_at_with_timeout at {:?} allowed delay: {:?}", at, timeout); - + tracing::debug!( + target: LOG_TARGET, + at = ?at, + allowed_delay = ?timeout, + "fatp::ready_at_with_timeout" + ); let timeout = futures_timer::Delay::new(timeout); let (view_already_exists, ready_at) = self.ready_at_internal(at); @@ -525,16 +548,16 @@ where let maybe_ready = async move { select! { - ready = ready_at => Some(ready), - _ = timeout => { - tracing::warn!(target: LOG_TARGET, - "Timeout fired waiting for transaction pool at block: ({:?}). \ - Proceeding with production.", - at, - ); - None - } - } + ready = ready_at => Some(ready), + _ = timeout => { + tracing::warn!( + target: LOG_TARGET, + at = ?at, + "Timeout fired waiting for transaction pool at block. Proceeding with production." + ); + None + } + } }; let fall_back_ready = self.ready_at_light(at); @@ -550,7 +573,12 @@ where let mut ready_poll = self.ready_poll.lock(); if let Some((view, inactive)) = self.view_store.get_view_at(at, true) { - tracing::debug!(target: LOG_TARGET, "fatp::ready_at_internal {at:?} (inactive:{inactive:?})"); + tracing::debug!( + target: LOG_TARGET, + at = ?at, + inactive = ?inactive, + "fatp::ready_at_internal" + ); let iterator: ReadyIteratorFor = Box::new(view.pool.validated_pool().ready()); return (true, async move { iterator }.boxed()); } @@ -559,14 +587,20 @@ where .add(at) .map(|received| { received.unwrap_or_else(|e| { - tracing::warn!(target: LOG_TARGET, "Error receiving ready-set iterator: {:?}", e); + tracing::warn!( + target: LOG_TARGET, + error = %e, + "Error receiving ready-set iterator" + ); Box::new(std::iter::empty()) }) }) .boxed(); - tracing::debug!(target: LOG_TARGET, - "fatp::ready_at_internal {at:?} pending keys: {:?}", - ready_poll.pollers.keys() + tracing::debug!( + target: LOG_TARGET, + at = ?at, + pending_keys = ?ready_poll.pollers.keys(), + "fatp::ready_at_internal" ); (false, pending) } @@ -644,7 +678,12 @@ where xts: Vec>, ) -> Result, Self::Error>>, Self::Error> { let view_store = self.view_store.clone(); - tracing::debug!(target: LOG_TARGET, "fatp::submit_at count:{} views:{}", xts.len(), self.active_views_count()); + tracing::debug!( + target: LOG_TARGET, + count = xts.len(), + views = self.active_views_count(), + "fatp::submit_at" + ); log_xt_trace!(target: LOG_TARGET, xts.iter().map(|xt| self.tx_hash(xt)), "[{:?}] fatp::submit_at"); let xts = xts.into_iter().map(Arc::from).collect::>(); let mempool_results = self.mempool.extend_unwatched(source, &xts); @@ -692,7 +731,12 @@ where source: TransactionSource, xt: TransactionFor, ) -> Result, Self::Error> { - tracing::trace!(target: LOG_TARGET, "[{:?}] fatp::submit_one views:{}", self.tx_hash(&xt), self.active_views_count()); + tracing::trace!( + target: LOG_TARGET, + tx_hash = ?self.tx_hash(&xt), + views = self.active_views_count(), + "fatp::submit_one" + ); match self.submit_at(_at, source, vec![xt]).await { Ok(mut v) => v.pop().expect("There is exactly one element in result of submit_at. qed."), @@ -710,7 +754,12 @@ where source: TransactionSource, xt: TransactionFor, ) -> Result>>, Self::Error> { - tracing::trace!(target: LOG_TARGET, "[{:?}] fatp::submit_and_watch views:{}", self.tx_hash(&xt), self.active_views_count()); + tracing::trace!( + target: LOG_TARGET, + tx_hash = ?self.tx_hash(&xt), + views = self.active_views_count(), + "fatp::submit_and_watch" + ); let xt = Arc::from(xt); let InsertionInfo { hash: xt_hash, source: timed_source } = match self.mempool.push_watched(source, xt.clone()) { @@ -734,7 +783,11 @@ where fn remove_invalid(&self, hashes: &[TxHash]) -> Vec> { if !hashes.is_empty() { tracing::debug!(target: LOG_TARGET, "fatp::remove_invalid {}", hashes.len()); - log_xt_trace!(target:LOG_TARGET, hashes, "[{:?}] fatp::remove_invalid"); + tracing::debug!( + target: LOG_TARGET, + count = hashes.len(), + "fatp::remove_invalid" + ); self.metrics .report(|metrics| metrics.removed_invalid_txs.inc_by(hashes.len() as _)); } @@ -786,9 +839,10 @@ where .flatten(); tracing::trace!( target: LOG_TARGET, - "[{tx_hash:?}] ready_transaction: {} {:?}", - result.is_some(), - most_recent_view + tx_hash = ?tx_hash, + result_is_some = result.is_some(), + most_recent_view = ?most_recent_view, + "ready_transaction" ); result } @@ -850,7 +904,11 @@ where _at: Block::Hash, xt: sc_transaction_pool_api::LocalTransactionFor, ) -> Result { - tracing::debug!(target: LOG_TARGET, "fatp::submit_local views:{}", self.active_views_count()); + tracing::debug!( + target: LOG_TARGET, + views = self.active_views_count(), + "fatp::submit_local" + ); let xt = Arc::from(xt); let InsertionInfo { hash: xt_hash, .. } = self .mempool @@ -880,8 +938,8 @@ where None => { tracing::warn!( target: LOG_TARGET, - "Skipping ChainEvent - no last block in tree route {:?}", - tree_route, + tree_route = ?tree_route, + "Skipping ChainEvent - no last block in tree route" ); return }, @@ -890,8 +948,8 @@ where if self.has_view(&hash_and_number.hash) { tracing::trace!( target: LOG_TARGET, - "view already exists for block: {:?}", - hash_and_number, + hash_and_number = ?hash_and_number, + "view already exists for block" ); return } @@ -928,10 +986,10 @@ where ) -> Option>> { tracing::debug!( target: LOG_TARGET, - "build_new_view: for: {:?} from: {:?} tree_route: {:?}", - at, - origin_view.as_ref().map(|v| v.at.clone()), - tree_route + at = ?at, + origin_view_at = ?origin_view.as_ref().map(|v| v.at.clone()), + tree_route = ?tree_route, + "build_new_view" ); let mut view = if let Some(origin_view) = origin_view { let mut view = View::new_from_other(&origin_view, at); @@ -940,7 +998,11 @@ where } view } else { - tracing::debug!(target: LOG_TARGET, "creating non-cloned view: for: {at:?}"); + tracing::debug!( + target: LOG_TARGET, + at = ?at, + "creating non-cloned view" + ); View::new( self.api.clone(), at.clone(), @@ -968,21 +1030,35 @@ where // sync the transactions statuses and referencing views in all the listeners with newly // cloned view. view.pool.validated_pool().retrigger_notifications(); - tracing::debug!(target: LOG_TARGET, "register_listeners: at {at:?} took {duration:?}"); + tracing::debug!( + target: LOG_TARGET, + at = ?at, + duration = ?duration, + "register_listeners" + ); // 2. Handle transactions from the tree route. Pruning transactions from the view first // will make some space for mempool transactions in case we are at the view's limits. let start = Instant::now(); self.update_view_with_fork(&view, tree_route, at.clone()).await; let duration = start.elapsed(); - tracing::debug!(target: LOG_TARGET, "update_view_with_fork: at {at:?} took {duration:?}"); + tracing::debug!( + target: LOG_TARGET, + at = ?at, + duration = ?duration, + "update_view_with_fork" + ); // 3. Finally, submit transactions from the mempool. let start = Instant::now(); self.update_view_with_mempool(&mut view, watched_xts).await; let duration = start.elapsed(); - tracing::debug!(target: LOG_TARGET, "update_view_with_mempool: at {at:?} took {duration:?}"); - + tracing::debug!( + target: LOG_TARGET, + at = ?at, + duration = ?duration, + "update_view_with_mempool" + ); let view = Arc::from(view); self.view_store.insert_new_view(view.clone(), tree_route).await; Some(view) @@ -1006,7 +1082,11 @@ where api.block_body(h.hash) .await .unwrap_or_else(|e| { - tracing::warn!(target: LOG_TARGET, "Compute ready light transactions: error request: {}", e); + tracing::warn!( + target: LOG_TARGET, + error = %e, + "Compute ready light transactions: error request" + ); None }) .unwrap_or_default() @@ -1017,12 +1097,13 @@ where }); } - tracing::debug!(target: LOG_TARGET, - "fatp::extrinsics_included_since_finalized {} from {} count: {} took:{:?}", - at, - recent_finalized_block, - all_extrinsics.len(), - start.elapsed() + tracing::debug!( + target: LOG_TARGET, + at = ?at, + recent_finalized_block = ?recent_finalized_block, + extrinsics_count = all_extrinsics.len(), + took = ?start.elapsed(), + "fatp::extrinsics_included_since_finalized" ); all_extrinsics } @@ -1039,10 +1120,10 @@ where ) -> Vec<(ExtrinsicHash, Arc>)> { tracing::debug!( target: LOG_TARGET, - "register_listeners: {:?} xts:{:?} v:{}", - view.at, - self.mempool.unwatched_and_watched_count(), - self.active_views_count() + view_at = ?view.at, + xts_count = ?self.mempool.unwatched_and_watched_count(), + active_views_count = self.active_views_count(), + "register_listeners" ); //todo [#5495]: maybe we don't need to register listener in view? We could use @@ -1055,7 +1136,12 @@ where let watcher = view.create_watcher(tx_hash); let at = view.at.clone(); async move { - tracing::trace!(target: LOG_TARGET, "[{:?}] adding watcher {:?}", tx_hash, at.hash); + tracing::trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + at_hash = ?at.hash, + "adding watcher" + ); self.view_store.listener.add_view_watcher_for_tx( tx_hash, at.hash, @@ -1089,10 +1175,10 @@ where ) { tracing::debug!( target: LOG_TARGET, - "update_view_with_mempool: {:?} xts:{:?} v:{}", - view.at, - self.mempool.unwatched_and_watched_count(), - self.active_views_count() + view_at = ?view.at, + xts_count = ?self.mempool.unwatched_and_watched_count(), + active_views_count = self.active_views_count(), + "update_view_with_mempool" ); let included_xts = self.extrinsics_included_since_finalized(view.at.hash).await; @@ -1116,10 +1202,10 @@ where tracing::debug!( target: LOG_TARGET, - "update_view_with_mempool: at {:?} submitted {}/{}", - view.at.hash, - submitted_count, - self.mempool.len() + view_at_hash = ?view.at.hash, + submitted_count = submitted_count, + mempool_len = self.mempool.len(), + "update_view_with_mempool" ); self.metrics @@ -1147,7 +1233,12 @@ where tree_route: &TreeRoute, hash_and_number: HashAndNumber, ) { - tracing::debug!(target: LOG_TARGET, "update_view_with_fork tree_route: {:?} {tree_route:?}", view.at); + tracing::debug!( + target: LOG_TARGET, + tree_route = ?tree_route, + view_at = ?view.at, + "update_view_with_fork" + ); let api = self.api.clone(); // We keep track of everything we prune so that later we won't add @@ -1177,7 +1268,11 @@ where .block_body(hash) .await .unwrap_or_else(|e| { - tracing::warn!(target: LOG_TARGET, "Failed to fetch block body: {}", e); + tracing::warn!( + target: LOG_TARGET, + error = %e, + "Failed to fetch block body" + ); None }) .unwrap_or_default() @@ -1234,8 +1329,13 @@ where /// - purging finalized transactions from the mempool and triggering mempool revalidation, async fn handle_finalized(&self, finalized_hash: Block::Hash, tree_route: &[Block::Hash]) { let finalized_number = self.api.block_id_to_number(&BlockId::Hash(finalized_hash)); - tracing::debug!(target: LOG_TARGET, "handle_finalized {finalized_number:?} tree_route: {tree_route:?} views_count:{}", self.active_views_count()); - + tracing::debug!( + target: LOG_TARGET, + finalized_number = ?finalized_number, + tree_route = ?tree_route, + views_count = self.active_views_count(), + "handle_finalized" + ); let finalized_xts = self.view_store.handle_finalized(finalized_hash, tree_route).await; self.mempool.purge_finalized_transactions(&finalized_xts).await; @@ -1252,11 +1352,19 @@ where ) .await; } else { - tracing::trace!(target: LOG_TARGET, "purge_transactions_later skipped, cannot find block number {finalized_number:?}"); + tracing::trace!( + target: LOG_TARGET, + finalized_number = ?finalized_number, + "purge_transactions_later skipped, cannot find block number" + ); } self.ready_poll.lock().remove_cancelled(); - tracing::trace!(target: LOG_TARGET, "handle_finalized after views_count:{:?}", self.active_views_count()); + tracing::trace!( + target: LOG_TARGET, + views_count = self.active_views_count(), + "handle_finalized after" + ); } /// Computes a hash of the provided transaction @@ -1275,7 +1383,11 @@ where /// Executes the maintainance for the given chain event. async fn maintain(&self, event: ChainEvent) { let start = Instant::now(); - tracing::debug!(target: LOG_TARGET, "processing event: {event:?}"); + tracing::debug!( + target: LOG_TARGET, + event = ?event, + "processing event" + ); self.view_store.finish_background_revalidations().await; @@ -1300,7 +1412,11 @@ where match result { Err(msg) => { - tracing::trace!(target: LOG_TARGET, "enactment_state::update error: {msg}"); + tracing::trace!( + target: LOG_TARGET, + error_message = %msg, + "enactment_state::update error" + ); self.enactment_state.lock().force_update(&event); }, Ok(EnactmentAction::Skip) => return, @@ -1328,8 +1444,9 @@ where tracing::trace!( target: LOG_TARGET, - "on-finalized enacted: {tree_route:?}, previously finalized: \ - {prev_finalized_block:?}", + tree_route = ?tree_route, + prev_finalized_block = ?prev_finalized_block, + "on-finalized enacted" ); }, } @@ -1338,11 +1455,12 @@ where tracing::info!( target: LOG_TARGET, - "maintain: txs:{:?} views:[{};{:?}] event:{event:?} took:{:?}", - self.mempool_len(), - self.active_views_count(), - self.views_stats(), - maintain_duration + mempool_len = format!("{:?}", self.mempool_len()), + active_views_count = self.active_views_count(), + views_stats = ?self.views_stats(), + event = ?event, + duration = ?maintain_duration, + "maintain" ); self.metrics.report(|metrics| { diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs index 9e65955f53e9..48544fa8d026 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs @@ -105,21 +105,29 @@ where let output_stream = futures::stream::unfold(ctx, |mut ctx| async move { loop { tokio::select! { - biased; - cmd = ctx.command_receiver.next() => { - match cmd? { - Command::AddView(key,stream) => { - trace!(target: LOG_TARGET,"Command::AddView {key:?}"); - ctx.stream_map.insert(key,stream); - }, - } - }, - - Some(event) = next_event(&mut ctx.stream_map) => { - trace!(target: LOG_TARGET, "import_notification_sink: select_next_some -> {:?}", event); - return Some((event.1, ctx)); - } - } + biased; + cmd = ctx.command_receiver.next() => { + match cmd? { + Command::AddView(key,stream) => { + trace!( + target: LOG_TARGET, + key = ?key, + "Command::AddView" + ); + ctx.stream_map.insert(key,stream); + }, + } + }, + + Some(event) = next_event(&mut ctx.stream_map) => { + trace!( + target: LOG_TARGET, + event = ?event, + "import_notification_sink: select_next_some" + ); + return Some((event.1, ctx)); + } + } } }) .boxed(); @@ -179,9 +187,17 @@ where async move { if already_notified_items.write().insert(event.clone()) { external_sinks.write().retain_mut(|sink| { - trace!(target: LOG_TARGET, "[{:?}] import_sink_worker sending out imported", event); + trace!( + target: LOG_TARGET, + event = ?event, + "import_sink_worker sending out imported" + ); if let Err(e) = sink.try_send(event.clone()) { - trace!(target: LOG_TARGET, "import_sink_worker sending message failed: {e}"); + trace!( + target: LOG_TARGET, + error = %e, + "import_sink_worker sending message failed" + ); false } else { true @@ -203,7 +219,12 @@ where .controller .unbounded_send(Command::AddView(key.clone(), view)) .map_err(|e| { - trace!(target: LOG_TARGET, "add_view {key:?} send message failed: {e}"); + trace!( + target: LOG_TARGET, + key = ?key, + error = %e, + "add_view send message failed" + ); }); } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs index 7bfbf3a6ca5b..de620650fce6 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs @@ -182,9 +182,14 @@ where hash: BlockHash, ) -> Option, BlockHash>> { trace!( - target: LOG_TARGET, "[{:?}] mvl handle event from {hash:?}: {status:?} views:{:?}", self.tx_hash, - self.status_stream_map.keys().collect::>() + target: LOG_TARGET, + tx_hash = ?self.tx_hash, + hash = ?hash, + status = ?status, + views = ?self.status_stream_map.keys().collect::>(), + "mvl handle event" ); + match status { TransactionStatus::Future => { self.views_keeping_tx_valid.insert(hash); @@ -238,8 +243,9 @@ where ); trace!( target: LOG_TARGET, - "[{:?}] got invalidate_transaction: views:{:?}", self.tx_hash, - self.status_stream_map.keys().collect::>() + tx_hash = ?self.tx_hash, + views = ?self.status_stream_map.keys().collect::>(), + "got invalidate_transaction" ); if self.views_keeping_tx_valid.is_disjoint(&keys) { self.terminate = true; @@ -261,7 +267,13 @@ where /// the stream map. fn add_stream(&mut self, block_hash: BlockHash, stream: TxStatusStream) { self.status_stream_map.insert(block_hash, stream); - trace!(target: LOG_TARGET, "[{:?}] AddView view: {:?} views:{:?}", self.tx_hash, block_hash, self.status_stream_map.keys().collect::>()); + trace!( + target: LOG_TARGET, + tx_hash = ?self.tx_hash, + block_hash = ?block_hash, + views = ?self.status_stream_map.keys().collect::>(), + "AddView view" + ); } /// Removes an existing transaction status stream. @@ -271,7 +283,13 @@ where fn remove_view(&mut self, block_hash: BlockHash) { self.status_stream_map.remove(&block_hash); self.views_keeping_tx_valid.remove(&block_hash); - trace!(target: LOG_TARGET, "[{:?}] RemoveView view: {:?} views:{:?}", self.tx_hash, block_hash, self.status_stream_map.keys().collect::>()); + trace!( + target: LOG_TARGET, + tx_hash = ?self.tx_hash, + block_hash = ?block_hash, + views = ?self.status_stream_map.keys().collect::>(), + "RemoveView view" + ); } } @@ -306,8 +324,11 @@ where return None } - trace!(target: LOG_TARGET, "[{:?}] create_external_watcher_for_tx", tx_hash); - + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + "create_external_watcher_for_tx" + ); let (tx, rx) = mpsc::tracing_unbounded("txpool-multi-view-listener", 32); controllers.insert(tx_hash, tx); @@ -323,14 +344,21 @@ where biased; Some((view_hash, status)) = next_event(&mut ctx.status_stream_map) => { if let Some(new_status) = ctx.handle(status, view_hash) { - trace!(target: LOG_TARGET, "[{:?}] mvl sending out: {new_status:?}", ctx.tx_hash); - return Some((new_status, ctx)) + trace!( + target: LOG_TARGET, + tx_hash = ?ctx.tx_hash, + new_status = ?new_status, + "mvl sending out" + ); + return Some((new_status, ctx)) } }, cmd = ctx.command_receiver.next() => { - trace!(target: LOG_TARGET, "[{:?}] select::rx views:{:?}", - ctx.tx_hash, - ctx.status_stream_map.keys().collect::>() + trace!( + target: LOG_TARGET, + tx_hash = ?ctx.tx_hash, + views = ?ctx.status_stream_map.keys().collect::>(), + "select::rx" ); match cmd? { ControllerCommand::AddViewStream(h,stream) => { @@ -341,26 +369,52 @@ where }, ControllerCommand::TransactionInvalidated => { if ctx.handle_invalidate_transaction() { - trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Invalid", ctx.tx_hash); + trace!( + target: LOG_TARGET, + tx_hash = ?ctx.tx_hash, + status = "Invalid", + "mvl sending out" + ); return Some((TransactionStatus::Invalid, ctx)) } }, ControllerCommand::FinalizeTransaction(block, index) => { - trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Finalized", ctx.tx_hash); + trace!( + target: LOG_TARGET, + tx_hash = ?ctx.tx_hash, + status = "Finalized", + "mvl sending out" + ); ctx.terminate = true; return Some((TransactionStatus::Finalized((block, index)), ctx)) }, ControllerCommand::TransactionBroadcasted(peers) => { - trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Broadcasted", ctx.tx_hash); + trace!( + target: LOG_TARGET, + tx_hash = ?ctx.tx_hash, + status = "Broadcasted", + "mvl sending out" + ); return Some((TransactionStatus::Broadcast(peers), ctx)) }, ControllerCommand::TransactionDropped(DroppedReason::LimitsEnforced) => { - trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Dropped", ctx.tx_hash); + trace!( + target: LOG_TARGET, + tx_hash = ?ctx.tx_hash, + status = "Dropped", + "mvl sending out" + ); ctx.terminate = true; return Some((TransactionStatus::Dropped, ctx)) }, ControllerCommand::TransactionDropped(DroppedReason::Usurped(by)) => { - trace!(target: LOG_TARGET, "[{:?}] mvl sending out: Usurped({:?})", ctx.tx_hash, by); + trace!( + target: LOG_TARGET, + tx_hash = ?ctx.tx_hash, + status = "Usurped", + by = ?by, + "mvl sending out" + ); ctx.terminate = true; return Some((TransactionStatus::Usurped(by), ctx)) }, @@ -390,7 +444,12 @@ where .get_mut() .unbounded_send(ControllerCommand::AddViewStream(block_hash, stream)) { - trace!(target: LOG_TARGET, "[{:?}] add_view_watcher_for_tx: send message failed: {:?}", tx_hash, e); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = ?e, + "add_view_watcher_for_tx: send message failed" + ); tx.remove(); } } @@ -405,7 +464,12 @@ where sender .unbounded_send(ControllerCommand::RemoveViewStream(block_hash)) .map_err(|e| { - trace!(target: LOG_TARGET, "[{:?}] remove_view: send message failed: {:?}", tx_hash, e); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = ?e, + "remove_view: send message failed" + ); e }) .is_ok() @@ -423,11 +487,20 @@ where let mut controllers = self.controllers.write(); invalid_hashes.iter().for_each(|tx_hash| { if let Entry::Occupied(mut tx) = controllers.entry(*tx_hash) { - trace!(target: LOG_TARGET, "[{:?}] invalidate_transaction", tx_hash); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + "invalidate_transaction" + ); if let Err(e) = tx.get_mut().unbounded_send(ControllerCommand::TransactionInvalidated) { - trace!(target: LOG_TARGET, "[{:?}] invalidate_transaction: send message failed: {:?}", tx_hash, e); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = ?e, + "invalidate_transaction: send message failed" + ); tx.remove(); } } @@ -445,9 +518,20 @@ where let mut controllers = self.controllers.write(); propagated.into_iter().for_each(|(tx_hash, peers)| { if let Entry::Occupied(mut tx) = controllers.entry(tx_hash) { - trace!(target: LOG_TARGET, "[{:?}] transaction_broadcasted", tx_hash); - if let Err(e) = tx.get_mut().unbounded_send(ControllerCommand::TransactionBroadcasted(peers)) { - trace!(target: LOG_TARGET, "[{:?}] transactions_broadcasted: send message failed: {:?}", tx_hash, e); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + "transaction_broadcasted" + ); + if let Err(e) = + tx.get_mut().unbounded_send(ControllerCommand::TransactionBroadcasted(peers)) + { + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = ?e, + "transactions_broadcasted: send message failed" + ); tx.remove(); } } @@ -460,12 +544,25 @@ where /// transaction prompting and external `Broadcasted` event. pub(crate) fn transaction_dropped(&self, dropped: DroppedTransaction>) { let mut controllers = self.controllers.write(); - debug!(target: LOG_TARGET, "mvl::transaction_dropped: {:?}", dropped); + debug!( + target: LOG_TARGET, + dropped = ?dropped, + "mvl::transaction_dropped" + ); if let Some(tx) = controllers.remove(&dropped.tx_hash) { let DroppedTransaction { tx_hash, reason } = dropped; - debug!(target: LOG_TARGET, "[{:?}] transaction_dropped", tx_hash); + debug!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + "transaction_dropped" + ); if let Err(e) = tx.unbounded_send(ControllerCommand::TransactionDropped(reason)) { - trace!(target: LOG_TARGET, "[{:?}] transaction_dropped: send message failed: {:?}", tx_hash, e); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = ?e, + "transaction_dropped: send message failed" + ); }; } } @@ -481,9 +578,18 @@ where ) { let mut controllers = self.controllers.write(); if let Some(tx) = controllers.remove(&tx_hash) { - trace!(target: LOG_TARGET, "[{:?}] finalize_transaction", tx_hash); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + "finalize_transaction" + ); if let Err(e) = tx.unbounded_send(ControllerCommand::FinalizeTransaction(block, idx)) { - trace!(target: LOG_TARGET, "[{:?}] finalize_transaction: send message failed: {:?}", tx_hash, e); + trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = ?e, + "finalize_transaction: send message failed" + ); } }; } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs index 4b9615654271..47edb7bf4322 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs @@ -133,8 +133,8 @@ where ) { tracing::trace!( target: LOG_TARGET, - "revalidation_queue::revalidate_view: Sending view to revalidation queue at {}", - view.at.hash + view_at_hash = ?view.at.hash, + "revalidation_queue::revalidate_view: Sending view to revalidation queue" ); if let Some(ref to_worker) = self.background { @@ -142,7 +142,11 @@ where view, finish_revalidation_worker_channels, )) { - tracing::warn!(target: LOG_TARGET, "revalidation_queue::revalidate_view: Failed to update background worker: {:?}", e); + tracing::warn!( + target: LOG_TARGET, + error = ?e, + "revalidation_queue::revalidate_view: Failed to update background worker" + ); } } else { view.revalidate(finish_revalidation_worker_channels).await @@ -163,15 +167,19 @@ where ) { tracing::trace!( target: LOG_TARGET, - "Sent mempool to revalidation queue at hash: {:?}", - finalized_hash + finalized_hash = ?finalized_hash, + "Sent mempool to revalidation queue" ); if let Some(ref to_worker) = self.background { if let Err(e) = to_worker.unbounded_send(WorkerPayload::RevalidateMempool(mempool, finalized_hash)) { - tracing::warn!(target: LOG_TARGET, "Failed to update background worker: {:?}", e); + tracing::warn!( + target: LOG_TARGET, + error = ?e, + "Failed to update background worker" + ); } } else { mempool.revalidate(finalized_hash).await diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs index ad6c7932b4a5..67f570c1e21b 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs @@ -295,8 +295,12 @@ where Err(sc_transaction_pool_api::error::Error::AlreadyImported(Box::new(hash)).into()), (false, _) => Err(sc_transaction_pool_api::error::Error::ImmediatelyDropped.into()), }; - tracing::trace!(target: LOG_TARGET, "[{:?}] mempool::try_insert: {:?}", hash, result.as_ref().map(|r| r.hash)); - + tracing::trace!( + target: LOG_TARGET, + hash = ?hash, + result_hash = ?result.as_ref().map(|r| r.hash), + "mempool::try_insert" + ); result } @@ -335,7 +339,11 @@ where &self, dropped: &ExtrinsicHash, ) -> Option>> { - tracing::debug!(target: LOG_TARGET, "[{:?}] mempool::remove_dropped_transaction", dropped); + tracing::debug!( + target: LOG_TARGET, + dropped = ?dropped, + "mempool::remove_dropped_transaction" + ); self.transactions.write().remove(dropped) } @@ -371,7 +379,11 @@ where /// /// Returns a vector of invalid transaction hashes. async fn revalidate_inner(&self, finalized_block: HashAndNumber) -> Vec { - tracing::trace!(target: LOG_TARGET, "mempool::revalidate at:{finalized_block:?}"); + tracing::trace!( + target: LOG_TARGET, + finalized_block = ?finalized_block, + "mempool::revalidate" + ); let start = Instant::now(); let (count, input) = { @@ -416,9 +428,9 @@ where Ok(Err(TransactionValidityError::Invalid(_))) => { tracing::trace!( target: LOG_TARGET, - "[{:?}]: Purging: invalid: {:?}", - xt_hash, - validation_result, + xt_hash = ?xt_hash, + validation_result = ?validation_result, + "Purging: invalid" ); Some(xt_hash) }, @@ -427,7 +439,12 @@ where tracing::debug!( target: LOG_TARGET, - "mempool::revalidate: at {finalized_block:?} count:{input_len}/{count} invalid_hashes:{} took {duration:?}", invalid_hashes.len(), + finalized_block = ?finalized_block, + input_len = input_len, + count = count, + invalid_hashes = invalid_hashes.len(), + duration = ?duration, + "mempool::revalidate" ); invalid_hashes @@ -438,7 +455,11 @@ where &self, finalized_xts: &Vec>, ) { - tracing::debug!(target: LOG_TARGET, "purge_finalized_transactions count:{:?}", finalized_xts.len()); + tracing::debug!( + target: LOG_TARGET, + count = finalized_xts.len(), + "purge_finalized_transactions" + ); log_xt_trace!(target: LOG_TARGET, finalized_xts, "[{:?}] purged finalized transactions"); let mut transactions = self.transactions.write(); finalized_xts.iter().for_each(|t| { @@ -449,7 +470,11 @@ where /// Revalidates transactions in the memory pool against a given finalized block and removes /// invalid ones. pub(super) async fn revalidate(&self, finalized_block: HashAndNumber) { - tracing::trace!(target: LOG_TARGET, "purge_transactions at:{:?}", finalized_block); + tracing::trace!( + target: LOG_TARGET, + finalized_block = ?finalized_block, + "purge_transactions" + ); let invalid_hashes = self.revalidate_inner(finalized_block.clone()).await; self.metrics.report(|metrics| { diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index 1493688a7fd8..050d00ed5d8e 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -174,7 +174,12 @@ where source: TimedTransactionSource, xt: ExtrinsicFor, ) -> Result, ExtrinsicHash>, ChainApi::Error> { - tracing::trace!(target: LOG_TARGET, "[{:?}] view::submit_and_watch at:{}", self.pool.validated_pool().api().hash_and_length(&xt).0, self.at.hash); + tracing::trace!( + target: LOG_TARGET, + tx_hash = ?self.pool.validated_pool().api().hash_and_length(&xt).0, + view_at_hash = ?self.at.hash, + "view::submit_and_watch" + ); self.pool.submit_and_watch(&self.at, source, xt).await } @@ -184,8 +189,12 @@ where xt: ExtrinsicFor, ) -> Result, ChainApi::Error> { let (hash, length) = self.pool.validated_pool().api().hash_and_length(&xt); - tracing::trace!(target: LOG_TARGET, "[{:?}] view::submit_local at:{}", hash, self.at.hash); - + tracing::trace!( + target: LOG_TARGET, + hash = ?hash, + view_at_hash = ?self.at.hash, + "view::submit_local" + ); let validity = self .pool .validated_pool() @@ -258,7 +267,11 @@ where revalidation_result_tx, } = finish_revalidation_worker_channels; - tracing::trace!(target:LOG_TARGET, "view::revalidate: at {} starting", self.at.hash); + tracing::trace!( + target: LOG_TARGET, + at_hash = ?self.at.hash, + "view::revalidate: at starting" + ); let start = Instant::now(); let validated_pool = self.pool.validated_pool(); let api = validated_pool.api(); @@ -278,20 +291,24 @@ where loop { let mut should_break = false; tokio::select! { - _ = finish_revalidation_request_rx.recv() => { - tracing::trace!(target: LOG_TARGET, "view::revalidate: finish revalidation request received at {}.", self.at.hash); - break - } - _ = async { - if let Some(tx) = batch_iter.next() { - let validation_result = (api.validate_transaction(self.at.hash, tx.source.clone().into(), tx.data.clone()).await, tx.hash, tx); - validation_results.push(validation_result); - } else { - self.revalidation_worker_channels.lock().as_mut().map(|ch| ch.remove_sender()); - should_break = true; - } - } => {} - } + _ = finish_revalidation_request_rx.recv() => { + tracing::trace!( + target: LOG_TARGET, + at_hash = ?self.at.hash, + "view::revalidate: finish revalidation request received" + ); + break + } + _ = async { + if let Some(tx) = batch_iter.next() { + let validation_result = (api.validate_transaction(self.at.hash, tx.source.clone().into(), tx.data.clone()).await, tx.hash, tx); + validation_results.push(validation_result); + } else { + self.revalidation_worker_channels.lock().as_mut().map(|ch| ch.remove_sender()); + should_break = true; + } + } => {} + } if should_break { break; @@ -303,12 +320,12 @@ where metrics.view_revalidation_duration.observe(revalidation_duration.as_secs_f64()); }); tracing::debug!( - target:LOG_TARGET, - "view::revalidate: at {:?} count: {}/{} took {:?}", - self.at.hash, - validation_results.len(), - batch_len, - revalidation_duration + target: LOG_TARGET, + at_hash = ?self.at.hash, + count = validation_results.len(), + batch_len = batch_len, + took = ?revalidation_duration, + "view::revalidate" ); log_xt_trace!(data:tuple, target:LOG_TARGET, validation_results.iter().map(|x| (x.1, &x.0)), "[{:?}] view::revalidateresult: {:?}"); @@ -333,30 +350,39 @@ where Ok(Err(TransactionValidityError::Unknown(e))) => { tracing::trace!( target: LOG_TARGET, - "[{:?}]: Removing. Cannot determine transaction validity: {:?}", - tx_hash, - e + tx_hash = ?tx_hash, + error = ?e, + "Removing. Cannot determine transaction validity" ); invalid_hashes.push(tx_hash); }, Err(validation_err) => { tracing::trace!( target: LOG_TARGET, - "[{:?}]: Removing due to error during revalidation: {}", - tx_hash, - validation_err + tx_hash = ?tx_hash, + error = %validation_err, + "Removing due to error during revalidation" ); invalid_hashes.push(tx_hash); }, } } - tracing::trace!(target:LOG_TARGET, "view::revalidate: sending revalidation result at {}", self.at.hash); + tracing::trace!( + target: LOG_TARGET, + at_hash = ?self.at.hash, + "view::revalidate: sending revalidation result" + ); if let Err(e) = revalidation_result_tx .send(RevalidationResult { invalid_hashes, revalidated }) .await { - tracing::trace!(target:LOG_TARGET, "view::revalidate: sending revalidation_result at {} failed {:?}", self.at.hash, e); + tracing::trace!( + target: LOG_TARGET, + at_hash = ?self.at.hash, + error = ?e, + "view::revalidate: sending revalidation_result failed" + ); } } @@ -374,7 +400,11 @@ where super::revalidation_worker::RevalidationQueue, >, ) { - tracing::trace!(target:LOG_TARGET,"view::start_background_revalidation: at {}", view.at.hash); + tracing::trace!( + target: LOG_TARGET, + at_hash = ?view.at.hash, + "view::start_background_revalidation" + ); let (finish_revalidation_request_tx, finish_revalidation_request_rx) = tokio::sync::mpsc::channel(1); let (revalidation_result_tx, revalidation_result_rx) = tokio::sync::mpsc::channel(1); @@ -404,7 +434,11 @@ where /// /// Refer to [*View revalidation*](../index.html#view-revalidation) for more details. pub(super) async fn finish_revalidation(&self) { - tracing::trace!(target:LOG_TARGET,"view::finish_revalidation: at {}", self.at.hash); + tracing::trace!( + target: LOG_TARGET, + at_hash = ?self.at.hash, + "view::finish_revalidation" + ); let Some(revalidation_worker_channels) = self.revalidation_worker_channels.lock().take() else { tracing::trace!(target:LOG_TARGET, "view::finish_revalidation: no finish_revalidation_request_tx"); @@ -418,7 +452,12 @@ where if let Some(finish_revalidation_request_tx) = finish_revalidation_request_tx { if let Err(e) = finish_revalidation_request_tx.send(()).await { - tracing::trace!(target:LOG_TARGET, "view::finish_revalidation: sending cancellation request at {} failed {:?}", self.at.hash, e); + tracing::trace!( + target: LOG_TARGET, + at_hash = ?self.at.hash, + error = ?e, + "view::finish_revalidation: sending cancellation request failed" + ); } } @@ -445,12 +484,12 @@ where }); tracing::debug!( - target:LOG_TARGET, - "view::finish_revalidation: applying revalidation result invalid: {} revalidated: {} at {:?} took {:?}", - revalidation_result.invalid_hashes.len(), - revalidated_len, - self.at.hash, - start.elapsed() + target: LOG_TARGET, + invalid = revalidation_result.invalid_hashes.len(), + revalidated = revalidated_len, + at_hash = ?self.at.hash, + took = ?start.elapsed(), + "view::finish_revalidation: applying revalidation result" ); } } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs index a3fbde87c983..d8829f87d8b9 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs @@ -169,7 +169,12 @@ where .find_or_first(Result::is_ok); if let Some(Err(err)) = result { - tracing::trace!(target: LOG_TARGET, "[{:?}] submit_local: err: {}", tx_hash, err); + tracing::trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = %err, + "submit_local: err" + ); return Err(err) }; @@ -223,7 +228,12 @@ where .find_or_first(Result::is_ok); if let Some(Err(err)) = maybe_error { - tracing::trace!(target: LOG_TARGET, "[{:?}] submit_and_watch: err: {}", tx_hash, err); + tracing::trace!( + target: LOG_TARGET, + tx_hash = ?tx_hash, + error = %err, + "submit_and_watch: err" + ); return Err(err); }; @@ -328,8 +338,12 @@ where finalized_hash: Block::Hash, tree_route: &[Block::Hash], ) -> Vec> { - tracing::trace!(target: LOG_TARGET, "finalize_route finalized_hash:{finalized_hash:?} tree_route: {tree_route:?}"); - + tracing::trace!( + target: LOG_TARGET, + finalized_hash = ?finalized_hash, + tree_route = ?tree_route, + "finalize_route" + ); let mut finalized_transactions = Vec::new(); for block in tree_route.iter().chain(std::iter::once(&finalized_hash)) { @@ -338,7 +352,11 @@ where .block_body(*block) .await .unwrap_or_else(|e| { - tracing::warn!(target: LOG_TARGET, "Finalize route: error request: {}", e); + tracing::warn!( + target: LOG_TARGET, + error = %e, + "Finalize route: error request" + ); None }) .unwrap_or_default() @@ -406,7 +424,11 @@ where active_views.insert(view.at.hash, view.clone()); most_recent_view_lock.replace(view.at.hash); }; - tracing::trace!(target:LOG_TARGET,"insert_new_view: inactive_views: {:?}", self.inactive_views.read().keys()); + tracing::trace!( + target: LOG_TARGET, + inactive_views = ?self.inactive_views.read().keys(), + "insert_new_view: inactive_views" + ); } /// Returns an optional reference to the view at given hash. @@ -463,8 +485,11 @@ where .for_each(drop); } - tracing::trace!(target:LOG_TARGET,"handle_pre_finalized: removed_views: {:?}", removed_views); - + tracing::trace!( + target: LOG_TARGET, + removed_views = ?removed_views, + "handle_pre_finalized" + ); removed_views.iter().for_each(|view| { self.dropped_stream_controller.remove_view(*view); }); @@ -519,10 +544,18 @@ where retain }); - tracing::trace!(target:LOG_TARGET,"handle_finalized: inactive_views: {:?}", inactive_views.keys()); + tracing::trace!( + target: LOG_TARGET, + inactive_views = ?inactive_views.keys(), + "handle_finalized" + ); } - tracing::trace!(target:LOG_TARGET,"handle_finalized: dropped_views: {:?}", dropped_views); + tracing::trace!( + target: LOG_TARGET, + dropped_views = ?dropped_views, + "handle_finalized" + ); self.listener.remove_stale_controllers(); self.dropped_stream_controller.remove_finalized_txs(finalized_xts.clone()); @@ -553,7 +586,11 @@ where .collect::>() }; futures::future::join_all(finish_revalidation_futures).await; - tracing::trace!(target:LOG_TARGET,"finish_background_revalidations took {:?}", start.elapsed()); + tracing::trace!( + target: LOG_TARGET, + took = ?start.elapsed(), + "finish_background_revalidations" + ); } /// Replaces an existing transaction in the view_store with a new one. @@ -582,7 +619,13 @@ where }; let xt_hash = self.api.hash_and_length(&xt).0; - tracing::trace!(target:LOG_TARGET,"[{replaced:?}] replace_transaction wtih {xt_hash:?}, w:{watched}"); + tracing::trace!( + target: LOG_TARGET, + replaced = ?replaced, + xt_hash = ?xt_hash, + watched = watched, + "replace_transaction" + ); self.replace_transaction_in_views(source, xt, xt_hash, replaced, watched).await; @@ -632,18 +675,22 @@ where }, Err(e) => { tracing::trace!( - target:LOG_TARGET, - "[{:?}] replace_transaction: submit_and_watch to {} failed {}", - xt_hash, view.at.hash, e + target: LOG_TARGET, + xt_hash = ?xt_hash, + at_hash = ?view.at.hash, + error = %e, + "replace_transaction: submit_and_watch failed" ); }, } } else { if let Some(Err(e)) = view.submit_many(std::iter::once((source, xt))).await.pop() { tracing::trace!( - target:LOG_TARGET, - "[{:?}] replace_transaction: submit to {} failed {}", - xt_hash, view.at.hash, e + target: LOG_TARGET, + xt_hash = ?xt_hash, + at_hash = ?view.at.hash, + error = %e, + "replace_transaction: submit failed" ); } } @@ -663,9 +710,9 @@ where ) { if watched && !self.listener.contains_tx(&xt_hash) { tracing::trace!( - target:LOG_TARGET, - "error: replace_transaction_in_views: no listener for watched transaction {:?}", - xt_hash, + target: LOG_TARGET, + xt_hash = ?xt_hash, + "error: replace_transaction_in_views: no listener for watched transaction" ); return; } From ba54f7126968a39246a0fa7aaa0d38917e07c31f Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 25 Jan 2025 10:03:44 +0100 Subject: [PATCH 06/15] simplification in logging --- .../fork_aware_txpool/fork_aware_txpool.rs | 101 +++++++++--------- .../import_notification_sink.rs | 74 ++++++------- .../fork_aware_txpool/multi_view_listener.rs | 64 +++++------ .../fork_aware_txpool/revalidation_worker.rs | 10 +- .../src/fork_aware_txpool/tx_mem_pool.rs | 20 ++-- .../src/fork_aware_txpool/view.rs | 18 ++-- .../src/fork_aware_txpool/view_store.rs | 48 ++++----- 7 files changed, 168 insertions(+), 167 deletions(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs index 979b8fa70fa4..06ddcaf2d130 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs @@ -469,10 +469,10 @@ where let extrinsics = api .block_body(h.hash) .await - .unwrap_or_else(|e| { + .unwrap_or_else(|error| { tracing::warn!( target: LOG_TARGET, - error = %e, + %error, "Compute ready light transactions: error request" ); None @@ -497,11 +497,11 @@ where let after_count = tmp_view.pool.validated_pool().status().ready; tracing::debug!( target: LOG_TARGET, - at = ?at, + ?at, best_view_hash = ?best_view.at.hash, - before_count = before_count, + before_count, to_be_removed = all_extrinsics.len(), - after_count = after_count, + after_count, took = ?start.elapsed(), "fatp::ready_at_light" ); @@ -510,7 +510,7 @@ where let empty: ReadyIteratorFor = Box::new(std::iter::empty()); tracing::debug!( target: LOG_TARGET, - at = ?at, + ?at, took = ?start.elapsed(), "fatp::ready_at_light -> empty" ); @@ -535,7 +535,7 @@ where ) -> ReadyIteratorFor { tracing::debug!( target: LOG_TARGET, - at = ?at, + ?at, allowed_delay = ?timeout, "fatp::ready_at_with_timeout" ); @@ -552,7 +552,7 @@ where _ = timeout => { tracing::warn!( target: LOG_TARGET, - at = ?at, + ?at, "Timeout fired waiting for transaction pool at block. Proceeding with production." ); None @@ -575,8 +575,8 @@ where if let Some((view, inactive)) = self.view_store.get_view_at(at, true) { tracing::debug!( target: LOG_TARGET, - at = ?at, - inactive = ?inactive, + ?at, + ?inactive, "fatp::ready_at_internal" ); let iterator: ReadyIteratorFor = Box::new(view.pool.validated_pool().ready()); @@ -586,10 +586,10 @@ where let pending = ready_poll .add(at) .map(|received| { - received.unwrap_or_else(|e| { + received.unwrap_or_else(|error| { tracing::warn!( target: LOG_TARGET, - error = %e, + %error, "Error receiving ready-set iterator" ); Box::new(std::iter::empty()) @@ -598,7 +598,7 @@ where .boxed(); tracing::debug!( target: LOG_TARGET, - at = ?at, + ?at, pending_keys = ?ready_poll.pollers.keys(), "fatp::ready_at_internal" ); @@ -782,7 +782,6 @@ where // useful for verification for debugging purposes). fn remove_invalid(&self, hashes: &[TxHash]) -> Vec> { if !hashes.is_empty() { - tracing::debug!(target: LOG_TARGET, "fatp::remove_invalid {}", hashes.len()); tracing::debug!( target: LOG_TARGET, count = hashes.len(), @@ -839,9 +838,9 @@ where .flatten(); tracing::trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, + ?tx_hash, result_is_some = result.is_some(), - most_recent_view = ?most_recent_view, + ?most_recent_view, "ready_transaction" ); result @@ -938,7 +937,7 @@ where None => { tracing::warn!( target: LOG_TARGET, - tree_route = ?tree_route, + ?tree_route, "Skipping ChainEvent - no last block in tree route" ); return @@ -948,7 +947,7 @@ where if self.has_view(&hash_and_number.hash) { tracing::trace!( target: LOG_TARGET, - hash_and_number = ?hash_and_number, + ?hash_and_number, "view already exists for block" ); return @@ -986,9 +985,9 @@ where ) -> Option>> { tracing::debug!( target: LOG_TARGET, - at = ?at, + ?at, origin_view_at = ?origin_view.as_ref().map(|v| v.at.clone()), - tree_route = ?tree_route, + ?tree_route, "build_new_view" ); let mut view = if let Some(origin_view) = origin_view { @@ -1000,7 +999,7 @@ where } else { tracing::debug!( target: LOG_TARGET, - at = ?at, + ?at, "creating non-cloned view" ); View::new( @@ -1032,8 +1031,8 @@ where view.pool.validated_pool().retrigger_notifications(); tracing::debug!( target: LOG_TARGET, - at = ?at, - duration = ?duration, + ?at, + ?duration, "register_listeners" ); @@ -1044,8 +1043,8 @@ where let duration = start.elapsed(); tracing::debug!( target: LOG_TARGET, - at = ?at, - duration = ?duration, + ?at, + ?duration, "update_view_with_fork" ); @@ -1055,8 +1054,8 @@ where let duration = start.elapsed(); tracing::debug!( target: LOG_TARGET, - at = ?at, - duration = ?duration, + ?at, + ?duration, "update_view_with_mempool" ); let view = Arc::from(view); @@ -1081,10 +1080,10 @@ where for h in tree_route.enacted().iter().rev() { api.block_body(h.hash) .await - .unwrap_or_else(|e| { + .unwrap_or_else(|error| { tracing::warn!( target: LOG_TARGET, - error = %e, + %error, "Compute ready light transactions: error request" ); None @@ -1099,8 +1098,8 @@ where tracing::debug!( target: LOG_TARGET, - at = ?at, - recent_finalized_block = ?recent_finalized_block, + ?at, + ?recent_finalized_block, extrinsics_count = all_extrinsics.len(), took = ?start.elapsed(), "fatp::extrinsics_included_since_finalized" @@ -1138,8 +1137,8 @@ where async move { tracing::trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - at_hash = ?at.hash, + ?tx_hash, + ?at.hash, "adding watcher" ); self.view_store.listener.add_view_watcher_for_tx( @@ -1203,7 +1202,7 @@ where tracing::debug!( target: LOG_TARGET, view_at_hash = ?view.at.hash, - submitted_count = submitted_count, + submitted_count, mempool_len = self.mempool.len(), "update_view_with_mempool" ); @@ -1235,8 +1234,8 @@ where ) { tracing::debug!( target: LOG_TARGET, - tree_route = ?tree_route, - view_at = ?view.at, + ?tree_route, + ?view.at, "update_view_with_fork" ); let api = self.api.clone(); @@ -1267,10 +1266,10 @@ where let block_transactions = api .block_body(hash) .await - .unwrap_or_else(|e| { + .unwrap_or_else(|error| { tracing::warn!( target: LOG_TARGET, - error = %e, + %error, "Failed to fetch block body" ); None @@ -1293,9 +1292,9 @@ where if !contains { tracing::trace!( target: LOG_TARGET, - "[{:?}]: Resubmitting from retracted block {:?}", - tx_hash, - hash, + ?tx_hash, + ?hash, + "Resubmitting from retracted block" ); } !contains @@ -1331,8 +1330,8 @@ where let finalized_number = self.api.block_id_to_number(&BlockId::Hash(finalized_hash)); tracing::debug!( target: LOG_TARGET, - finalized_number = ?finalized_number, - tree_route = ?tree_route, + ?finalized_number, + ?tree_route, views_count = self.active_views_count(), "handle_finalized" ); @@ -1354,7 +1353,7 @@ where } else { tracing::trace!( target: LOG_TARGET, - finalized_number = ?finalized_number, + ?finalized_number, "purge_transactions_later skipped, cannot find block number" ); } @@ -1385,7 +1384,7 @@ where let start = Instant::now(); tracing::debug!( target: LOG_TARGET, - event = ?event, + ?event, "processing event" ); @@ -1411,10 +1410,10 @@ where .update(&event, &compute_tree_route, &block_id_to_number); match result { - Err(msg) => { + Err(error) => { tracing::trace!( target: LOG_TARGET, - error_message = %msg, + %error, "enactment_state::update error" ); self.enactment_state.lock().force_update(&event); @@ -1444,8 +1443,8 @@ where tracing::trace!( target: LOG_TARGET, - tree_route = ?tree_route, - prev_finalized_block = ?prev_finalized_block, + ?tree_route, + ?prev_finalized_block, "on-finalized enacted" ); }, @@ -1458,8 +1457,8 @@ where mempool_len = format!("{:?}", self.mempool_len()), active_views_count = self.active_views_count(), views_stats = ?self.views_stats(), - event = ?event, - duration = ?maintain_duration, + ?event, + ?maintain_duration, "maintain" ); diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs index 48544fa8d026..1ca287fa2371 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/import_notification_sink.rs @@ -105,29 +105,29 @@ where let output_stream = futures::stream::unfold(ctx, |mut ctx| async move { loop { tokio::select! { - biased; - cmd = ctx.command_receiver.next() => { - match cmd? { - Command::AddView(key,stream) => { - trace!( - target: LOG_TARGET, - key = ?key, - "Command::AddView" - ); - ctx.stream_map.insert(key,stream); - }, - } - }, - - Some(event) = next_event(&mut ctx.stream_map) => { - trace!( - target: LOG_TARGET, - event = ?event, - "import_notification_sink: select_next_some" - ); - return Some((event.1, ctx)); - } - } + biased; + cmd = ctx.command_receiver.next() => { + match cmd? { + Command::AddView(key,stream) => { + trace!( + target: LOG_TARGET, + ?key, + "Command::AddView" + ); + ctx.stream_map.insert(key,stream); + }, + } + }, + + Some(event) = next_event(&mut ctx.stream_map) => { + trace!( + target: LOG_TARGET, + ?event, + "import_notification_sink: select_next_some" + ); + return Some((event.1, ctx)); + } + } } }) .boxed(); @@ -189,13 +189,13 @@ where external_sinks.write().retain_mut(|sink| { trace!( target: LOG_TARGET, - event = ?event, + ?event, "import_sink_worker sending out imported" ); - if let Err(e) = sink.try_send(event.clone()) { + if let Err(error) = sink.try_send(event.clone()) { trace!( target: LOG_TARGET, - error = %e, + %error, "import_sink_worker sending message failed" ); false @@ -215,17 +215,17 @@ where /// The new view's stream is added to the internal aggregated stream context by sending command /// to its `command_receiver`. pub fn add_view(&self, key: K, view: StreamOf) { - let _ = self - .controller - .unbounded_send(Command::AddView(key.clone(), view)) - .map_err(|e| { - trace!( - target: LOG_TARGET, - key = ?key, - error = %e, - "add_view send message failed" - ); - }); + let _ = + self.controller + .unbounded_send(Command::AddView(key.clone(), view)) + .map_err(|error| { + trace!( + target: LOG_TARGET, + ?key, + %error, + "add_view send message failed" + ); + }); } /// Creates and returns a new external stream of ready transactions hashes notifications. diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs index de620650fce6..a513559a7cd5 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/multi_view_listener.rs @@ -184,8 +184,8 @@ where trace!( target: LOG_TARGET, tx_hash = ?self.tx_hash, - hash = ?hash, - status = ?status, + ?hash, + ?status, views = ?self.status_stream_map.keys().collect::>(), "mvl handle event" ); @@ -270,7 +270,7 @@ where trace!( target: LOG_TARGET, tx_hash = ?self.tx_hash, - block_hash = ?block_hash, + ?block_hash, views = ?self.status_stream_map.keys().collect::>(), "AddView view" ); @@ -286,7 +286,7 @@ where trace!( target: LOG_TARGET, tx_hash = ?self.tx_hash, - block_hash = ?block_hash, + ?block_hash, views = ?self.status_stream_map.keys().collect::>(), "RemoveView view" ); @@ -326,7 +326,7 @@ where trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, + ?tx_hash, "create_external_watcher_for_tx" ); let (tx, rx) = mpsc::tracing_unbounded("txpool-multi-view-listener", 32); @@ -347,7 +347,7 @@ where trace!( target: LOG_TARGET, tx_hash = ?ctx.tx_hash, - new_status = ?new_status, + ?new_status, "mvl sending out" ); return Some((new_status, ctx)) @@ -412,7 +412,7 @@ where target: LOG_TARGET, tx_hash = ?ctx.tx_hash, status = "Usurped", - by = ?by, + ?by, "mvl sending out" ); ctx.terminate = true; @@ -440,14 +440,14 @@ where let mut controllers = self.controllers.write(); if let Entry::Occupied(mut tx) = controllers.entry(tx_hash) { - if let Err(e) = tx + if let Err(error) = tx .get_mut() .unbounded_send(ControllerCommand::AddViewStream(block_hash, stream)) { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = ?e, + ?tx_hash, + %error, "add_view_watcher_for_tx: send message failed" ); tx.remove(); @@ -463,14 +463,14 @@ where self.controllers.write().retain(|tx_hash, sender| { sender .unbounded_send(ControllerCommand::RemoveViewStream(block_hash)) - .map_err(|e| { + .map_err(|error| { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = ?e, + ?tx_hash, + %error, "remove_view: send message failed" ); - e + error }) .is_ok() }); @@ -489,16 +489,16 @@ where if let Entry::Occupied(mut tx) = controllers.entry(*tx_hash) { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, + ?tx_hash, "invalidate_transaction" ); - if let Err(e) = + if let Err(error) = tx.get_mut().unbounded_send(ControllerCommand::TransactionInvalidated) { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = ?e, + ?tx_hash, + %error, "invalidate_transaction: send message failed" ); tx.remove(); @@ -520,16 +520,16 @@ where if let Entry::Occupied(mut tx) = controllers.entry(tx_hash) { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, + ?tx_hash, "transaction_broadcasted" ); - if let Err(e) = + if let Err(error) = tx.get_mut().unbounded_send(ControllerCommand::TransactionBroadcasted(peers)) { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = ?e, + ?tx_hash, + %error, "transactions_broadcasted: send message failed" ); tx.remove(); @@ -546,21 +546,21 @@ where let mut controllers = self.controllers.write(); debug!( target: LOG_TARGET, - dropped = ?dropped, + ?dropped, "mvl::transaction_dropped" ); if let Some(tx) = controllers.remove(&dropped.tx_hash) { let DroppedTransaction { tx_hash, reason } = dropped; debug!( target: LOG_TARGET, - tx_hash = ?tx_hash, + ?tx_hash, "transaction_dropped" ); - if let Err(e) = tx.unbounded_send(ControllerCommand::TransactionDropped(reason)) { + if let Err(error) = tx.unbounded_send(ControllerCommand::TransactionDropped(reason)) { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = ?e, + ?tx_hash, + %error, "transaction_dropped: send message failed" ); }; @@ -580,14 +580,16 @@ where if let Some(tx) = controllers.remove(&tx_hash) { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, + ?tx_hash, "finalize_transaction" ); - if let Err(e) = tx.unbounded_send(ControllerCommand::FinalizeTransaction(block, idx)) { + if let Err(error) = + tx.unbounded_send(ControllerCommand::FinalizeTransaction(block, idx)) + { trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = ?e, + ?tx_hash, + %error, "finalize_transaction: send message failed" ); } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs index 47edb7bf4322..cabbbbff09cd 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs @@ -138,13 +138,13 @@ where ); if let Some(ref to_worker) = self.background { - if let Err(e) = to_worker.unbounded_send(WorkerPayload::RevalidateView( + if let Err(error) = to_worker.unbounded_send(WorkerPayload::RevalidateView( view, finish_revalidation_worker_channels, )) { tracing::warn!( target: LOG_TARGET, - error = ?e, + ?error, "revalidation_queue::revalidate_view: Failed to update background worker" ); } @@ -167,17 +167,17 @@ where ) { tracing::trace!( target: LOG_TARGET, - finalized_hash = ?finalized_hash, + ?finalized_hash, "Sent mempool to revalidation queue" ); if let Some(ref to_worker) = self.background { - if let Err(e) = + if let Err(error) = to_worker.unbounded_send(WorkerPayload::RevalidateMempool(mempool, finalized_hash)) { tracing::warn!( target: LOG_TARGET, - error = ?e, + ?error, "Failed to update background worker" ); } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs index 67f570c1e21b..493beded9272 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs @@ -297,7 +297,7 @@ where }; tracing::trace!( target: LOG_TARGET, - hash = ?hash, + ?hash, result_hash = ?result.as_ref().map(|r| r.hash), "mempool::try_insert" ); @@ -341,7 +341,7 @@ where ) -> Option>> { tracing::debug!( target: LOG_TARGET, - dropped = ?dropped, + ?dropped, "mempool::remove_dropped_transaction" ); self.transactions.write().remove(dropped) @@ -381,7 +381,7 @@ where async fn revalidate_inner(&self, finalized_block: HashAndNumber) -> Vec { tracing::trace!( target: LOG_TARGET, - finalized_block = ?finalized_block, + ?finalized_block, "mempool::revalidate" ); let start = Instant::now(); @@ -428,8 +428,8 @@ where Ok(Err(TransactionValidityError::Invalid(_))) => { tracing::trace!( target: LOG_TARGET, - xt_hash = ?xt_hash, - validation_result = ?validation_result, + ?xt_hash, + ?validation_result, "Purging: invalid" ); Some(xt_hash) @@ -439,11 +439,11 @@ where tracing::debug!( target: LOG_TARGET, - finalized_block = ?finalized_block, - input_len = input_len, - count = count, + ?finalized_block, + input_len, + count, invalid_hashes = invalid_hashes.len(), - duration = ?duration, + ?duration, "mempool::revalidate" ); @@ -472,7 +472,7 @@ where pub(super) async fn revalidate(&self, finalized_block: HashAndNumber) { tracing::trace!( target: LOG_TARGET, - finalized_block = ?finalized_block, + ?finalized_block, "purge_transactions" ); let invalid_hashes = self.revalidate_inner(finalized_block.clone()).await; diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index 050d00ed5d8e..c9198612faaa 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -191,7 +191,7 @@ where let (hash, length) = self.pool.validated_pool().api().hash_and_length(&xt); tracing::trace!( target: LOG_TARGET, - hash = ?hash, + ?hash, view_at_hash = ?self.at.hash, "view::submit_local" ); @@ -323,7 +323,7 @@ where target: LOG_TARGET, at_hash = ?self.at.hash, count = validation_results.len(), - batch_len = batch_len, + batch_len, took = ?revalidation_duration, "view::revalidate" ); @@ -347,11 +347,11 @@ where ), ); }, - Ok(Err(TransactionValidityError::Unknown(e))) => { + Ok(Err(TransactionValidityError::Unknown(error))) => { tracing::trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = ?e, + ?tx_hash, + ?error, "Removing. Cannot determine transaction validity" ); invalid_hashes.push(tx_hash); @@ -359,8 +359,8 @@ where Err(validation_err) => { tracing::trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = %validation_err, + ?tx_hash, + %validation_err, "Removing due to error during revalidation" ); invalid_hashes.push(tx_hash); @@ -373,14 +373,14 @@ where at_hash = ?self.at.hash, "view::revalidate: sending revalidation result" ); - if let Err(e) = revalidation_result_tx + if let Err(error) = revalidation_result_tx .send(RevalidationResult { invalid_hashes, revalidated }) .await { tracing::trace!( target: LOG_TARGET, at_hash = ?self.at.hash, - error = ?e, + ?error, "view::revalidate: sending revalidation_result failed" ); } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs index d8829f87d8b9..1502abdf4856 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs @@ -168,14 +168,14 @@ where .map(|view| view.submit_local(xt.clone())) .find_or_first(Result::is_ok); - if let Some(Err(err)) = result { + if let Some(Err(error)) = result { tracing::trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = %err, + ?tx_hash, + %error, "submit_local: err" ); - return Err(err) + return Err(error) }; Ok(tx_hash) @@ -227,14 +227,14 @@ where .into_iter() .find_or_first(Result::is_ok); - if let Some(Err(err)) = maybe_error { + if let Some(Err(error)) = maybe_error { tracing::trace!( target: LOG_TARGET, - tx_hash = ?tx_hash, - error = %err, + ?tx_hash, + %error, "submit_and_watch: err" ); - return Err(err); + return Err(error); }; Ok(external_watcher) @@ -340,8 +340,8 @@ where ) -> Vec> { tracing::trace!( target: LOG_TARGET, - finalized_hash = ?finalized_hash, - tree_route = ?tree_route, + ?finalized_hash, + ?tree_route, "finalize_route" ); let mut finalized_transactions = Vec::new(); @@ -351,10 +351,10 @@ where .api .block_body(*block) .await - .unwrap_or_else(|e| { + .unwrap_or_else(|error| { tracing::warn!( target: LOG_TARGET, - error = %e, + %error, "Finalize route: error request" ); None @@ -487,7 +487,7 @@ where tracing::trace!( target: LOG_TARGET, - removed_views = ?removed_views, + ?removed_views, "handle_pre_finalized" ); removed_views.iter().for_each(|view| { @@ -553,7 +553,7 @@ where tracing::trace!( target: LOG_TARGET, - dropped_views = ?dropped_views, + ?dropped_views, "handle_finalized" ); @@ -621,9 +621,9 @@ where let xt_hash = self.api.hash_and_length(&xt).0; tracing::trace!( target: LOG_TARGET, - replaced = ?replaced, - xt_hash = ?xt_hash, - watched = watched, + ?replaced, + ?xt_hash, + watched, "replace_transaction" ); @@ -673,23 +673,23 @@ where watcher.into_stream().boxed(), ); }, - Err(e) => { + Err(error) => { tracing::trace!( target: LOG_TARGET, - xt_hash = ?xt_hash, + ?xt_hash, at_hash = ?view.at.hash, - error = %e, + %error, "replace_transaction: submit_and_watch failed" ); }, } } else { - if let Some(Err(e)) = view.submit_many(std::iter::once((source, xt))).await.pop() { + if let Some(Err(error)) = view.submit_many(std::iter::once((source, xt))).await.pop() { tracing::trace!( target: LOG_TARGET, - xt_hash = ?xt_hash, + ?xt_hash, at_hash = ?view.at.hash, - error = %e, + %error, "replace_transaction: submit failed" ); } @@ -711,7 +711,7 @@ where if watched && !self.listener.contains_tx(&xt_hash) { tracing::trace!( target: LOG_TARGET, - xt_hash = ?xt_hash, + ?xt_hash, "error: replace_transaction_in_views: no listener for watched transaction" ); return; From cbf1316085514fe0025751076a03095cc5af4305 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 25 Jan 2025 10:10:38 +0100 Subject: [PATCH 07/15] merge conflict resolving --- .../src/fork_aware_txpool/view.rs | 4 +-- .../src/fork_aware_txpool/view_store.rs | 26 +++++++++---------- 2 files changed, 15 insertions(+), 15 deletions(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index a2a5fb80a40f..145119bf5fa5 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -159,7 +159,7 @@ where &self, xts: impl IntoIterator)>, ) -> Vec, ChainApi::Error>> { - if tracing::enabled!(target: LOG_TARGET, tracing::Level::TRACE) { + if tracing::enabled!(target: LOG_TARGET, tracing::Level::TRACE) { let xts = xts.into_iter().collect::>(); log_xt_trace!(target: LOG_TARGET, xts.iter().map(|(_,xt)| self.pool.validated_pool().api().hash_and_length(xt).0), "[{:?}] view::submit_many at:{}", self.at.hash); self.pool.submit_at(&self.at, xts).await @@ -174,7 +174,7 @@ where source: TimedTransactionSource, xt: ExtrinsicFor, ) -> Result, ChainApi::Error> { - tracing::trace!( + tracing::trace!( target: LOG_TARGET, tx_hash = ?self.pool.validated_pool().api().hash_and_length(&xt).0, view_at_hash = ?self.at.hash, diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs index 999fced32564..1bb8f54bd10f 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs @@ -259,12 +259,12 @@ where match result { Some(Err(error)) => { - tracing::trace!( - target: LOG_TARGET, - ?tx_hash, - %error, - "submit_local: err" - ); + tracing::trace!( + target: LOG_TARGET, + ?tx_hash, + %error, + "submit_local: err" + ); Err(error) }, None => Ok(ViewStoreSubmitOutcome::new(tx_hash, None)), @@ -320,13 +320,13 @@ where match result { Some(Err(error)) => { - tracing::trace!( - target: LOG_TARGET, - ?tx_hash, - %error, - "submit_and_watch: err" - ); - return Err(error); + tracing::trace!( + target: LOG_TARGET, + ?tx_hash, + %error, + "submit_and_watch: err" + ); + return Err(error); }, Some(Ok(result)) => Ok(ViewStoreSubmitOutcome::from(result).with_watcher(external_watcher)), From 5ecd8ae44a030ac7985d1d0fa8fbce0f964bd95c Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Sat, 25 Jan 2025 10:32:01 +0100 Subject: [PATCH 08/15] resolving conversations --- .../src/common/tracing_log_xt.rs | 8 ++-- .../fork_aware_txpool/fork_aware_txpool.rs | 38 +++++++++---------- 2 files changed, 21 insertions(+), 25 deletions(-) diff --git a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs index b80f049f1b22..6cbf8f373644 100644 --- a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs +++ b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs @@ -5,7 +5,7 @@ macro_rules! log_xt { $level, target = $target, message = $text_with_format, - tx = format!("{:?}", tx) + tx_hash = format!("{:?}", tx) ); } }; @@ -15,7 +15,7 @@ macro_rules! log_xt { $level, target = $target, message = $text_with_format, - tx = format!("{:?}", tx), + tx_hash = format!("{:?}", tx), $($arg),* ); } @@ -26,8 +26,8 @@ macro_rules! log_xt { $level, target = $target, message = $text_with_format, - tx_0 = format!("{:?}", tx.0), - tx_1 = format!("{:?}", tx.1) + tx_hash = format!("{:?}", tx.0), + some_value = format!("{:?}", tx.1) ); } }; diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs index efcc7c4482c5..7b5f12cae54e 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs @@ -268,10 +268,10 @@ where tracing::debug!(target: LOG_TARGET, "fatp::dropped_monitor_task: terminated..."); break; }; - let dropped_tx_hash = dropped.tx_hash; + let tx_hash = dropped.tx_hash; tracing::trace!( target: LOG_TARGET, - ?dropped_tx_hash, + ?tx_hash, reason = ?dropped.reason, "fatp::dropped notification, removing" ); @@ -282,7 +282,7 @@ where .replace_transaction( new_tx.source(), new_tx.tx(), - dropped_tx_hash, + tx_hash, new_tx.is_watched(), ) .await; @@ -297,9 +297,9 @@ where DroppedReason::LimitsEnforced => {}, }; - mempool.remove_transaction(&dropped_tx_hash); + mempool.remove_transaction(&tx_hash); view_store.listener.transaction_dropped(dropped); - import_notification_sink.clean_notified_items(&[dropped_tx_hash]); + import_notification_sink.clean_notified_items(&[tx_hash]); } } @@ -440,7 +440,7 @@ where let api = self.api.clone(); tracing::trace!( target: LOG_TARGET, - at = ?at, + ?at, "fatp::ready_at_light" ); @@ -553,16 +553,16 @@ where let maybe_ready = async move { select! { - ready = ready_at => Some(ready), - _ = timeout => { - tracing::warn!( - target: LOG_TARGET, - ?at, - "Timeout fired waiting for transaction pool at block. Proceeding with production." - ); - None - } - } + ready = ready_at => Some(ready), + _ = timeout => { + tracing::warn!( + target: LOG_TARGET, + ?at, + "Timeout fired waiting for transaction pool at block. Proceeding with production." + ); + None + } + } }; let fall_back_ready = self.ready_at_light(at); @@ -840,11 +840,7 @@ where // useful for verification for debugging purposes). fn remove_invalid(&self, hashes: &[TxHash]) -> Vec> { if !hashes.is_empty() { - tracing::debug!( - target: LOG_TARGET, - count = hashes.len(), - "fatp::remove_invalid" - ); + log_xt_trace!(target:LOG_TARGET, hashes, "fatp::remove_invalid"); self.metrics .report(|metrics| metrics.removed_invalid_txs.inc_by(hashes.len() as _)); } From 2102068ce7e59155836a8e2a29deb2e785815eb7 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Mon, 27 Jan 2025 16:45:18 +0100 Subject: [PATCH 09/15] license header + doc --- .../src/common/tracing_log_xt.rs | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs index 6cbf8f373644..3ea2ddf2b589 100644 --- a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs +++ b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs @@ -1,3 +1,19 @@ +// This file is part of Substrate. +// Copyright (C) Parity Technologies (UK) Ltd. +// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0 +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// You should have received a copy of the GNU General Public License +// along with this program. If not, see . +//! Utility for logging transaction collections with tracing crate. + +/// Logs every transaction from given `tx_collection` with given level. macro_rules! log_xt { (data: hash, target: $target:expr, $level:expr, $tx_collection:expr, $text_with_format:expr) => { for tx in $tx_collection { From 2cda6bf039364a7bf469245c47308cf240eed13c Mon Sep 17 00:00:00 2001 From: Michal Kucharczyk <1728078+michalkucharczyk@users.noreply.github.com> Date: Wed, 29 Jan 2025 14:38:35 +0100 Subject: [PATCH 10/15] tracing_log_xt improvements, log_xt removed from fork-aware-txpool --- .../transaction-pool/src/common/tracing_log_xt.rs | 10 +++++----- .../src/fork_aware_txpool/dropped_watcher.rs | 2 +- .../src/fork_aware_txpool/fork_aware_txpool.rs | 2 +- .../src/fork_aware_txpool/tx_mem_pool.rs | 2 +- .../transaction-pool/src/fork_aware_txpool/view.rs | 6 +++--- substrate/client/transaction-pool/src/graph/future.rs | 4 ++-- substrate/client/transaction-pool/src/graph/pool.rs | 4 ++-- .../transaction-pool/src/graph/validated_pool.rs | 4 ++-- 8 files changed, 17 insertions(+), 17 deletions(-) diff --git a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs index 3ea2ddf2b589..f4cd8462a07c 100644 --- a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs +++ b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs @@ -20,8 +20,8 @@ macro_rules! log_xt { tracing::event!( $level, target = $target, - message = $text_with_format, - tx_hash = format!("{:?}", tx) + tx_hash = format!("{:?}", tx), + $text_with_format, ); } }; @@ -30,8 +30,8 @@ macro_rules! log_xt { tracing::event!( $level, target = $target, - message = $text_with_format, tx_hash = format!("{:?}", tx), + $text_with_format, $($arg),* ); } @@ -41,9 +41,9 @@ macro_rules! log_xt { tracing::event!( $level, target = $target, - message = $text_with_format, tx_hash = format!("{:?}", tx.0), - some_value = format!("{:?}", tx.1) + $text_with_format, + tx.1 ); } }; diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs index e930f2bd5746..3588645344ba 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/dropped_watcher.rs @@ -225,7 +225,7 @@ where log_xt_trace!( target: LOG_TARGET, xts.clone(), - "[{:?}] dropped_watcher: finalized xt removed" + "dropped_watcher: finalized xt removed" ); xts.iter().for_each(|xt| { self.ready_transaction_views.remove(xt); diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs index 7b5f12cae54e..90695e8ef262 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs @@ -689,7 +689,7 @@ where views = self.active_views_count(), "fatp::submit_at" ); - log_xt_trace!(target: LOG_TARGET, xts.iter().map(|xt| self.tx_hash(xt)), "[{:?}] fatp::submit_at"); + log_xt_trace!(target: LOG_TARGET, xts.iter().map(|xt| self.tx_hash(xt)), "fatp::submit_at"); let xts = xts.into_iter().map(Arc::from).collect::>(); let mempool_results = self.mempool.extend_unwatched(source, &xts); diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs index 346b23013761..367aa429d76b 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs @@ -581,7 +581,7 @@ where count = finalized_xts.len(), "purge_finalized_transactions" ); - log_xt_trace!(target: LOG_TARGET, finalized_xts, "[{:?}] purged finalized transactions"); + log_xt_trace!(target: LOG_TARGET, finalized_xts, "purged finalized transactions"); let mut transactions = self.transactions.write(); finalized_xts.iter().for_each(|t| { transactions.remove(t); diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index 145119bf5fa5..f72051f96752 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -25,7 +25,7 @@ use super::metrics::MetricsLink as PrometheusMetrics; use crate::{ - common::log_xt::log_xt_trace, + common::tracing_log_xt::log_xt_trace, graph::{ self, base_pool::TimedTransactionSource, watcher::Watcher, ExtrinsicFor, ExtrinsicHash, IsValidator, ValidatedPoolSubmitOutcome, ValidatedTransaction, ValidatedTransactionFor, @@ -161,7 +161,7 @@ where ) -> Vec, ChainApi::Error>> { if tracing::enabled!(target: LOG_TARGET, tracing::Level::TRACE) { let xts = xts.into_iter().collect::>(); - log_xt_trace!(target: LOG_TARGET, xts.iter().map(|(_,xt)| self.pool.validated_pool().api().hash_and_length(xt).0), "[{:?}] view::submit_many at:{}", self.at.hash); + log_xt_trace!(target: LOG_TARGET, xts.iter().map(|(_,xt)| self.pool.validated_pool().api().hash_and_length(xt).0), "view::submit_many at:{}", self.at.hash); self.pool.submit_at(&self.at, xts).await } else { self.pool.submit_at(&self.at, xts).await @@ -327,7 +327,7 @@ where took = ?revalidation_duration, "view::revalidate" ); - log_xt_trace!(data:tuple, target:LOG_TARGET, validation_results.iter().map(|x| (x.1, &x.0)), "[{:?}] view::revalidateresult: {:?}"); + log_xt_trace!(data:tuple, target:LOG_TARGET, validation_results.iter().map(|x| (x.1, &x.0)), "view::revalidate result: {:?}"); for (validation_result, tx_hash, tx) in validation_results { match validation_result { diff --git a/substrate/client/transaction-pool/src/graph/future.rs b/substrate/client/transaction-pool/src/graph/future.rs index 2c1e64c04b7f..848893b026c5 100644 --- a/substrate/client/transaction-pool/src/graph/future.rs +++ b/substrate/client/transaction-pool/src/graph/future.rs @@ -27,7 +27,7 @@ use sp_runtime::transaction_validity::TransactionTag as Tag; use std::time::Instant; use super::base_pool::Transaction; -use crate::{common::log_xt::log_xt_trace, LOG_TARGET}; +use crate::{common::tracing_log_xt::log_xt_trace, LOG_TARGET}; /// Transaction with partially satisfied dependencies. pub struct WaitingTransaction { @@ -184,7 +184,7 @@ impl }) .collect::>(); - log_xt_trace!(target: LOG_TARGET, &pruned, "[{:?}] FutureTransactions: removed while pruning tags."); + log_xt_trace!(target: LOG_TARGET, &pruned, "FutureTransactions: removed while pruning tags."); self.remove(&pruned) } diff --git a/substrate/client/transaction-pool/src/graph/pool.rs b/substrate/client/transaction-pool/src/graph/pool.rs index 403712662ada..52b12e3fabae 100644 --- a/substrate/client/transaction-pool/src/graph/pool.rs +++ b/substrate/client/transaction-pool/src/graph/pool.rs @@ -16,7 +16,7 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . -use crate::{common::log_xt::log_xt_trace, LOG_TARGET}; +use crate::{common::tracing_log_xt::log_xt_trace, LOG_TARGET}; use futures::{channel::mpsc::Receiver, Future}; use indexmap::IndexMap; use sc_transaction_pool_api::error; @@ -395,7 +395,7 @@ impl Pool { let pruned_hashes = reverified_transactions.keys().map(Clone::clone).collect::>(); log::debug!(target: LOG_TARGET, "Pruning at {:?}. Resubmitting transactions: {}, reverification took: {:?}", &at, reverified_transactions.len(), now.elapsed()); - log_xt_trace!(data: tuple, target: LOG_TARGET, &reverified_transactions, "[{:?}] Resubmitting transaction: {:?}"); + log_xt_trace!(data: tuple, target: LOG_TARGET, &reverified_transactions, "Resubmitting transaction: {:?}"); // And finally - submit reverified transactions back to the pool self.validated_pool.resubmit_pruned( diff --git a/substrate/client/transaction-pool/src/graph/validated_pool.rs b/substrate/client/transaction-pool/src/graph/validated_pool.rs index bc2b07896dba..bbfcb9b40aca 100644 --- a/substrate/client/transaction-pool/src/graph/validated_pool.rs +++ b/substrate/client/transaction-pool/src/graph/validated_pool.rs @@ -21,7 +21,7 @@ use std::{ sync::Arc, }; -use crate::{common::log_xt::log_xt_trace, LOG_TARGET}; +use crate::{common::tracing_log_xt::log_xt_trace, LOG_TARGET}; use futures::channel::mpsc::{channel, Sender}; use parking_lot::{Mutex, RwLock}; use sc_transaction_pool_api::{error, PoolStatus, ReadyTransactions, TransactionPriority}; @@ -706,7 +706,7 @@ impl ValidatedPool { let invalid = self.pool.write().remove_subtree(hashes); log::trace!(target: LOG_TARGET, "Removed invalid transactions: {:?}", invalid.len()); - log_xt_trace!(target: LOG_TARGET, invalid.iter().map(|t| t.hash), "{:?} Removed invalid transaction"); + log_xt_trace!(target: LOG_TARGET, invalid.iter().map(|t| t.hash), "Removed invalid transaction"); let mut listener = self.listener.write(); for tx in &invalid { From f8c361b1ec51af59c881dc2d151cd3bf50449d18 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Wed, 29 Jan 2025 16:32:47 +0100 Subject: [PATCH 11/15] nits on conversation --- .../fork_aware_txpool/fork_aware_txpool.rs | 101 +++++++++--------- .../fork_aware_txpool/revalidation_worker.rs | 9 +- .../src/fork_aware_txpool/tx_mem_pool.rs | 78 ++++++++------ .../src/fork_aware_txpool/view.rs | 81 +++++++------- .../src/fork_aware_txpool/view_store.rs | 53 ++++----- 5 files changed, 167 insertions(+), 155 deletions(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs index 90695e8ef262..594f5e85230e 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs @@ -70,6 +70,7 @@ use std::{ time::Instant, }; use tokio::select; +use tracing::{debug, info, trace, warn}; /// Fork aware transaction pool task, that needs to be polled. pub type ForkAwareTxPoolTask = Pin + Send>>; @@ -105,10 +106,10 @@ where /// /// `ready_iterator` is a closure that generates the result data to be sent to the pollers. fn trigger(&mut self, at: Block::Hash, ready_iterator: impl Fn() -> T) { - tracing::trace!(target: LOG_TARGET, ?at, keys = ?self.pollers.keys(), "fatp::trigger"); + trace!(target: LOG_TARGET, ?at, keys = ?self.pollers.keys(), "fatp::trigger"); let Some(pollers) = self.pollers.remove(&at) else { return }; pollers.into_iter().for_each(|p| { - tracing::debug!(target: LOG_TARGET, "trigger ready signal at block {}", at); + debug!(target: LOG_TARGET, "trigger ready signal at block {}", at); let _ = p.send(ready_iterator()); }); } @@ -265,11 +266,11 @@ where ) { loop { let Some(dropped) = dropped_stream.next().await else { - tracing::debug!(target: LOG_TARGET, "fatp::dropped_monitor_task: terminated..."); + debug!(target: LOG_TARGET, "fatp::dropped_monitor_task: terminated..."); break; }; let tx_hash = dropped.tx_hash; - tracing::trace!( + trace!( target: LOG_TARGET, ?tx_hash, reason = ?dropped.reason, @@ -287,7 +288,7 @@ where ) .await; } else { - tracing::trace!( + trace!( target: LOG_TARGET, tx_hash = ?new_tx_hash, "error: dropped_monitor_task: no entry in mempool for new transaction" @@ -438,7 +439,7 @@ where pub async fn ready_at_light(&self, at: Block::Hash) -> ReadyIteratorFor { let start = Instant::now(); let api = self.api.clone(); - tracing::trace!( + trace!( target: LOG_TARGET, ?at, "fatp::ready_at_light" @@ -475,7 +476,7 @@ where .block_body(h.hash) .await .unwrap_or_else(|error| { - tracing::warn!( + warn!( target: LOG_TARGET, %error, "Compute ready light transactions: error request" @@ -500,23 +501,23 @@ where let _ = tmp_view.pool.validated_pool().prune_tags(tags); let after_count = tmp_view.pool.validated_pool().status().ready; - tracing::debug!( + debug!( target: LOG_TARGET, ?at, best_view_hash = ?best_view.at.hash, before_count, to_be_removed = all_extrinsics.len(), after_count, - took = ?start.elapsed(), + duration = ?start.elapsed(), "fatp::ready_at_light" ); Box::new(tmp_view.pool.validated_pool().ready()) } else { let empty: ReadyIteratorFor = Box::new(std::iter::empty()); - tracing::debug!( + debug!( target: LOG_TARGET, ?at, - took = ?start.elapsed(), + duration = ?start.elapsed(), "fatp::ready_at_light -> empty" ); empty @@ -538,7 +539,7 @@ where at: Block::Hash, timeout: std::time::Duration, ) -> ReadyIteratorFor { - tracing::debug!( + debug!( target: LOG_TARGET, ?at, allowed_delay = ?timeout, @@ -555,7 +556,7 @@ where select! { ready = ready_at => Some(ready), _ = timeout => { - tracing::warn!( + warn!( target: LOG_TARGET, ?at, "Timeout fired waiting for transaction pool at block. Proceeding with production." @@ -578,7 +579,7 @@ where let mut ready_poll = self.ready_poll.lock(); if let Some((view, inactive)) = self.view_store.get_view_at(at, true) { - tracing::debug!( + debug!( target: LOG_TARGET, ?at, ?inactive, @@ -592,7 +593,7 @@ where .add(at) .map(|received| { received.unwrap_or_else(|error| { - tracing::warn!( + warn!( target: LOG_TARGET, %error, "Error receiving ready-set iterator" @@ -601,7 +602,7 @@ where }) }) .boxed(); - tracing::debug!( + debug!( target: LOG_TARGET, ?at, pending_keys = ?ready_poll.pollers.keys(), @@ -683,7 +684,7 @@ where xts: Vec>, ) -> Result, Self::Error>>, Self::Error> { let view_store = self.view_store.clone(); - tracing::debug!( + debug!( target: LOG_TARGET, count = xts.len(), views = self.active_views_count(), @@ -780,7 +781,7 @@ where source: TransactionSource, xt: TransactionFor, ) -> Result, Self::Error> { - tracing::trace!( + trace!( target: LOG_TARGET, tx_hash = ?self.tx_hash(&xt), views = self.active_views_count(), @@ -803,7 +804,7 @@ where source: TransactionSource, xt: TransactionFor, ) -> Result>>, Self::Error> { - tracing::trace!( + trace!( target: LOG_TARGET, tx_hash = ?self.tx_hash(&xt), views = self.active_views_count(), @@ -890,7 +891,7 @@ where let result = most_recent_view .map(|block_hash| self.view_store.ready_transaction(block_hash, tx_hash)) .flatten(); - tracing::trace!( + trace!( target: LOG_TARGET, ?tx_hash, result_is_some = result.is_some(), @@ -951,7 +952,7 @@ where _at: Block::Hash, xt: sc_transaction_pool_api::LocalTransactionFor, ) -> Result { - tracing::debug!( + debug!( target: LOG_TARGET, views = self.active_views_count(), "fatp::submit_local" @@ -1000,7 +1001,7 @@ where let hash_and_number = match tree_route.last() { Some(hash_and_number) => hash_and_number, None => { - tracing::warn!( + warn!( target: LOG_TARGET, ?tree_route, "Skipping ChainEvent - no last block in tree route" @@ -1010,7 +1011,7 @@ where }; if self.has_view(&hash_and_number.hash) { - tracing::trace!( + trace!( target: LOG_TARGET, ?hash_and_number, "view already exists for block" @@ -1048,7 +1049,7 @@ where at: &HashAndNumber, tree_route: &TreeRoute, ) -> Option>> { - tracing::debug!( + debug!( target: LOG_TARGET, ?at, origin_view_at = ?origin_view.as_ref().map(|v| v.at.clone()), @@ -1062,7 +1063,7 @@ where } view } else { - tracing::debug!( + debug!( target: LOG_TARGET, ?at, "creating non-cloned view" @@ -1094,7 +1095,7 @@ where // sync the transactions statuses and referencing views in all the listeners with newly // cloned view. view.pool.validated_pool().retrigger_notifications(); - tracing::debug!( + debug!( target: LOG_TARGET, ?at, ?duration, @@ -1106,7 +1107,7 @@ where let start = Instant::now(); self.update_view_with_fork(&view, tree_route, at.clone()).await; let duration = start.elapsed(); - tracing::debug!( + debug!( target: LOG_TARGET, ?at, ?duration, @@ -1117,7 +1118,7 @@ where let start = Instant::now(); self.update_view_with_mempool(&mut view, watched_xts).await; let duration = start.elapsed(); - tracing::debug!( + debug!( target: LOG_TARGET, ?at, ?duration, @@ -1146,7 +1147,7 @@ where api.block_body(h.hash) .await .unwrap_or_else(|error| { - tracing::warn!( + warn!( target: LOG_TARGET, %error, "Compute ready light transactions: error request" @@ -1161,12 +1162,12 @@ where }); } - tracing::debug!( + debug!( target: LOG_TARGET, ?at, ?recent_finalized_block, extrinsics_count = all_extrinsics.len(), - took = ?start.elapsed(), + duration = ?start.elapsed(), "fatp::extrinsics_included_since_finalized" ); all_extrinsics @@ -1182,7 +1183,7 @@ where &self, view: &View, ) -> Vec<(ExtrinsicHash, Arc>)> { - tracing::debug!( + debug!( target: LOG_TARGET, view_at = ?view.at, xts_count = ?self.mempool.unwatched_and_watched_count(), @@ -1200,10 +1201,10 @@ where let watcher = view.create_watcher(tx_hash); let at = view.at.clone(); async move { - tracing::trace!( + trace!( target: LOG_TARGET, ?tx_hash, - ?at.hash, + at = ?at.hash, "adding watcher" ); self.view_store.listener.add_view_watcher_for_tx( @@ -1237,7 +1238,7 @@ where view: &View, watched_xts: Vec<(ExtrinsicHash, Arc>)>, ) { - tracing::debug!( + debug!( target: LOG_TARGET, view_at = ?view.at, xts_count = ?self.mempool.unwatched_and_watched_count(), @@ -1268,7 +1269,7 @@ where let submitted_count = watched_results.len(); - tracing::debug!( + debug!( target: LOG_TARGET, view_at_hash = ?view.at.hash, submitted_count, @@ -1301,10 +1302,10 @@ where tree_route: &TreeRoute, hash_and_number: HashAndNumber, ) { - tracing::debug!( + debug!( target: LOG_TARGET, ?tree_route, - ?view.at, + at = ?view.at, "update_view_with_fork" ); let api = self.api.clone(); @@ -1336,7 +1337,7 @@ where .block_body(hash) .await .unwrap_or_else(|error| { - tracing::warn!( + warn!( target: LOG_TARGET, %error, "Failed to fetch block body" @@ -1359,7 +1360,7 @@ where resubmitted_to_report += 1; if !contains { - tracing::trace!( + trace!( target: LOG_TARGET, ?tx_hash, ?hash, @@ -1397,7 +1398,7 @@ where /// - purging finalized transactions from the mempool and triggering mempool revalidation, async fn handle_finalized(&self, finalized_hash: Block::Hash, tree_route: &[Block::Hash]) { let finalized_number = self.api.block_id_to_number(&BlockId::Hash(finalized_hash)); - tracing::debug!( + debug!( target: LOG_TARGET, ?finalized_number, ?tree_route, @@ -1420,7 +1421,7 @@ where ) .await; } else { - tracing::trace!( + trace!( target: LOG_TARGET, ?finalized_number, "purge_transactions_later skipped, cannot find block number" @@ -1428,7 +1429,7 @@ where } self.ready_poll.lock().remove_cancelled(); - tracing::trace!( + trace!( target: LOG_TARGET, views_count = self.active_views_count(), "handle_finalized after" @@ -1546,7 +1547,7 @@ where /// Executes the maintainance for the given chain event. async fn maintain(&self, event: ChainEvent) { let start = Instant::now(); - tracing::debug!( + debug!( target: LOG_TARGET, ?event, "processing event" @@ -1575,7 +1576,7 @@ where match result { Err(error) => { - tracing::trace!( + trace!( target: LOG_TARGET, %error, "enactment_state::update error" @@ -1605,7 +1606,7 @@ where ChainEvent::Finalized { hash, ref tree_route } => { self.handle_finalized(hash, tree_route).await; - tracing::trace!( + trace!( target: LOG_TARGET, ?tree_route, ?prev_finalized_block, @@ -1614,15 +1615,15 @@ where }, } - let maintain_duration = start.elapsed(); + let duration = start.elapsed(); - tracing::info!( + info!( target: LOG_TARGET, mempool_len = format!("{:?}", self.mempool_len()), active_views_count = self.active_views_count(), views_stats = ?self.views_stats(), ?event, - ?maintain_duration, + ?duration, "maintain" ); @@ -1634,7 +1635,7 @@ where watched.try_into().map(|v| metrics.watched_txs.set(v)), unwatched.try_into().map(|v| metrics.unwatched_txs.set(v)), ); - metrics.maintain_duration.observe(maintain_duration.as_secs_f64()); + metrics.maintain_duration.observe(duration.as_secs_f64()); }); } } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs index cabbbbff09cd..0025d3e9f2d4 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/revalidation_worker.rs @@ -30,6 +30,7 @@ use sp_runtime::traits::Block as BlockT; use super::tx_mem_pool::TxMemPool; use futures::prelude::*; +use tracing::{trace, warn}; use super::view::{FinishRevalidationWorkerChannels, View}; @@ -131,7 +132,7 @@ where view: Arc>, finish_revalidation_worker_channels: FinishRevalidationWorkerChannels, ) { - tracing::trace!( + trace!( target: LOG_TARGET, view_at_hash = ?view.at.hash, "revalidation_queue::revalidate_view: Sending view to revalidation queue" @@ -142,7 +143,7 @@ where view, finish_revalidation_worker_channels, )) { - tracing::warn!( + warn!( target: LOG_TARGET, ?error, "revalidation_queue::revalidate_view: Failed to update background worker" @@ -165,7 +166,7 @@ where mempool: Arc>, finalized_hash: HashAndNumber, ) { - tracing::trace!( + trace!( target: LOG_TARGET, ?finalized_hash, "Sent mempool to revalidation queue" @@ -175,7 +176,7 @@ where if let Err(error) = to_worker.unbounded_send(WorkerPayload::RevalidateMempool(mempool, finalized_hash)) { - tracing::warn!( + warn!( target: LOG_TARGET, ?error, "Failed to update background worker" diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs index 367aa429d76b..f2b019fc8bce 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs @@ -26,33 +26,38 @@ //! it), while on other forks tx can be valid. Depending on which view is chosen to be cloned, //! such transaction could not be present in the newly created view. -use super::{ - metrics::MetricsLink as PrometheusMetrics, multi_view_listener::MultiViewListener, - view_store::ViewStoreSubmitOutcome, -}; -use crate::{ - common::tracing_log_xt::log_xt_trace, - graph, - graph::{base_pool::TimedTransactionSource, tracked_map::Size, ExtrinsicFor, ExtrinsicHash}, - LOG_TARGET, +use std::{ + cmp::Ordering, + collections::HashMap, + sync::{ + atomic::{self, AtomicU64}, + Arc, + }, + time::Instant, }; + use futures::FutureExt; use itertools::Itertools; use parking_lot::RwLock; +use tracing::{debug, trace}; + use sc_transaction_pool_api::{TransactionPriority, TransactionSource}; use sp_blockchain::HashAndNumber; use sp_runtime::{ traits::Block as BlockT, transaction_validity::{InvalidTransaction, TransactionValidityError}, }; -use std::{ - cmp::Ordering, - collections::HashMap, - sync::{ - atomic::{self, AtomicU64}, - Arc, - }, - time::Instant, + +use crate::{ + common::tracing_log_xt::log_xt_trace, + graph, + graph::{base_pool::TimedTransactionSource, tracked_map::Size, ExtrinsicFor, ExtrinsicHash}, + LOG_TARGET, +}; + +use super::{ + metrics::MetricsLink as PrometheusMetrics, multi_view_listener::MultiViewListener, + view_store::ViewStoreSubmitOutcome, }; /// The minimum interval between single transaction revalidations. Given in blocks. @@ -324,7 +329,7 @@ where /// exceed the maximum allowed transaction count. fn try_insert( &self, - hash: ExtrinsicHash, + tx_hash: ExtrinsicHash, tx: TxInMemPool, ) -> Result>, sc_transaction_pool_api::error::Error> { let mut transactions = self.transactions.write(); @@ -333,20 +338,20 @@ where let result = match ( self.is_limit_exceeded(transactions.len() + 1, bytes + tx.bytes), - transactions.contains_key(&hash), + transactions.contains_key(&tx_hash), ) { (false, false) => { let source = tx.source(); - transactions.insert(hash, Arc::from(tx)); - Ok(InsertionInfo::new(hash, source)) + transactions.insert(tx_hash, Arc::from(tx)); + Ok(InsertionInfo::new(tx_hash, source)) }, (_, true) => - Err(sc_transaction_pool_api::error::Error::AlreadyImported(Box::new(hash))), + Err(sc_transaction_pool_api::error::Error::AlreadyImported(Box::new(tx_hash))), (true, _) => Err(sc_transaction_pool_api::error::Error::ImmediatelyDropped), }; - tracing::trace!( + trace!( target: LOG_TARGET, - ?hash, + ?tx_hash, result_hash = ?result.as_ref().map(|r| r.hash), "mempool::try_insert" ); @@ -492,7 +497,7 @@ where &self, hash: &ExtrinsicHash, ) -> Option>> { - log::debug!(target: LOG_TARGET, "[{hash:?}] mempool::remove_transaction"); + debug!(target: LOG_TARGET, ?hash, "mempool::remove_transaction"); self.transactions.write().remove(hash) } @@ -500,7 +505,7 @@ where /// /// Returns a vector of invalid transaction hashes. async fn revalidate_inner(&self, finalized_block: HashAndNumber) -> Vec { - tracing::trace!( + trace!( target: LOG_TARGET, ?finalized_block, "mempool::revalidate" @@ -541,24 +546,24 @@ where let invalid_hashes = validation_results .into_iter() - .filter_map(|(xt_hash, validation_result)| match validation_result { + .filter_map(|(tx_hash, validation_result)| match validation_result { Ok(Ok(_)) | Ok(Err(TransactionValidityError::Invalid(InvalidTransaction::Future))) => None, Err(_) | Ok(Err(TransactionValidityError::Unknown(_))) | Ok(Err(TransactionValidityError::Invalid(_))) => { - tracing::trace!( + trace!( target: LOG_TARGET, - ?xt_hash, + ?tx_hash, ?validation_result, "Purging: invalid" ); - Some(xt_hash) + Some(tx_hash) }, }) .collect::>(); - tracing::debug!( + debug!( target: LOG_TARGET, ?finalized_block, input_len, @@ -576,7 +581,7 @@ where &self, finalized_xts: &Vec>, ) { - tracing::debug!( + debug!( target: LOG_TARGET, count = finalized_xts.len(), "purge_finalized_transactions" @@ -591,7 +596,7 @@ where /// Revalidates transactions in the memory pool against a given finalized block and removes /// invalid ones. pub(super) async fn revalidate(&self, finalized_block: HashAndNumber) { - tracing::trace!( + trace!( target: LOG_TARGET, ?finalized_block, "purge_transactions" @@ -623,10 +628,13 @@ where #[cfg(test)] mod tx_mem_pool_tests { - use super::*; - use crate::{common::tests::TestApi, graph::ChainApi}; use substrate_test_runtime::{AccountId, Extrinsic, ExtrinsicBuilder, Transfer, H256}; use substrate_test_runtime_client::Sr25519Keyring::*; + + use crate::{common::tests::TestApi, graph::ChainApi}; + + use super::*; + fn uxt(nonce: u64) -> Extrinsic { crate::common::tests::uxt(Transfer { from: Alice.into(), diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index f72051f96752..88e5809cc8a5 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -40,6 +40,7 @@ use sp_runtime::{ SaturatedConversion, }; use std::{collections::HashMap, sync::Arc, time::Instant}; +use tracing::{debug, trace}; pub(super) struct RevalidationResult { revalidated: HashMap, ValidatedTransactionFor>, @@ -174,7 +175,7 @@ where source: TimedTransactionSource, xt: ExtrinsicFor, ) -> Result, ChainApi::Error> { - tracing::trace!( + trace!( target: LOG_TARGET, tx_hash = ?self.pool.validated_pool().api().hash_and_length(&xt).0, view_at_hash = ?self.at.hash, @@ -188,10 +189,10 @@ where &self, xt: ExtrinsicFor, ) -> Result, ChainApi::Error> { - let (hash, length) = self.pool.validated_pool().api().hash_and_length(&xt); - tracing::trace!( + let (tx_hash, length) = self.pool.validated_pool().api().hash_and_length(&xt); + trace!( target: LOG_TARGET, - ?hash, + ?tx_hash, view_at_hash = ?self.at.hash, "view::submit_local" ); @@ -221,7 +222,7 @@ where let validated = ValidatedTransaction::valid_at( block_number.saturated_into::(), - hash, + tx_hash, TimedTransactionSource::new_local(true), Arc::from(xt), length, @@ -267,7 +268,7 @@ where revalidation_result_tx, } = finish_revalidation_worker_channels; - tracing::trace!( + trace!( target: LOG_TARGET, at_hash = ?self.at.hash, "view::revalidate: at starting" @@ -291,24 +292,24 @@ where loop { let mut should_break = false; tokio::select! { - _ = finish_revalidation_request_rx.recv() => { - tracing::trace!( - target: LOG_TARGET, - at_hash = ?self.at.hash, - "view::revalidate: finish revalidation request received" - ); - break - } - _ = async { - if let Some(tx) = batch_iter.next() { - let validation_result = (api.validate_transaction(self.at.hash, tx.source.clone().into(), tx.data.clone()).await, tx.hash, tx); - validation_results.push(validation_result); - } else { - self.revalidation_worker_channels.lock().as_mut().map(|ch| ch.remove_sender()); - should_break = true; - } - } => {} - } + _ = finish_revalidation_request_rx.recv() => { + trace!( + target: LOG_TARGET, + at_hash = ?self.at.hash, + "view::revalidate: finish revalidation request received" + ); + break + } + _ = async { + if let Some(tx) = batch_iter.next() { + let validation_result = (api.validate_transaction(self.at.hash, tx.source.clone().into(), tx.data.clone()).await, tx.hash, tx); + validation_results.push(validation_result); + } else { + self.revalidation_worker_channels.lock().as_mut().map(|ch| ch.remove_sender()); + should_break = true; + } + } => {} + } if should_break { break; @@ -319,15 +320,15 @@ where self.metrics.report(|metrics| { metrics.view_revalidation_duration.observe(revalidation_duration.as_secs_f64()); }); - tracing::debug!( + debug!( target: LOG_TARGET, at_hash = ?self.at.hash, count = validation_results.len(), batch_len, - took = ?revalidation_duration, + duration = ?revalidation_duration, "view::revalidate" ); - log_xt_trace!(data:tuple, target:LOG_TARGET, validation_results.iter().map(|x| (x.1, &x.0)), "view::revalidate result: {:?}"); + log_xt_trace!(data:tuple, target:LOG_TARGET, validation_results.iter().map(|x| (x.1, &x.0)), "view::revalidateresult: {:?}"); for (validation_result, tx_hash, tx) in validation_results { match validation_result { @@ -348,7 +349,7 @@ where ); }, Ok(Err(TransactionValidityError::Unknown(error))) => { - tracing::trace!( + trace!( target: LOG_TARGET, ?tx_hash, ?error, @@ -356,11 +357,11 @@ where ); invalid_hashes.push(tx_hash); }, - Err(validation_err) => { - tracing::trace!( + Err(error) => { + trace!( target: LOG_TARGET, ?tx_hash, - %validation_err, + %error, "Removing due to error during revalidation" ); invalid_hashes.push(tx_hash); @@ -368,7 +369,7 @@ where } } - tracing::trace!( + trace!( target: LOG_TARGET, at_hash = ?self.at.hash, "view::revalidate: sending revalidation result" @@ -377,7 +378,7 @@ where .send(RevalidationResult { invalid_hashes, revalidated }) .await { - tracing::trace!( + trace!( target: LOG_TARGET, at_hash = ?self.at.hash, ?error, @@ -400,7 +401,7 @@ where super::revalidation_worker::RevalidationQueue, >, ) { - tracing::trace!( + trace!( target: LOG_TARGET, at_hash = ?view.at.hash, "view::start_background_revalidation" @@ -434,14 +435,14 @@ where /// /// Refer to [*View revalidation*](../index.html#view-revalidation) for more details. pub(super) async fn finish_revalidation(&self) { - tracing::trace!( + trace!( target: LOG_TARGET, at_hash = ?self.at.hash, "view::finish_revalidation" ); let Some(revalidation_worker_channels) = self.revalidation_worker_channels.lock().take() else { - tracing::trace!(target:LOG_TARGET, "view::finish_revalidation: no finish_revalidation_request_tx"); + trace!(target:LOG_TARGET, "view::finish_revalidation: no finish_revalidation_request_tx"); return }; @@ -451,11 +452,11 @@ where } = revalidation_worker_channels; if let Some(finish_revalidation_request_tx) = finish_revalidation_request_tx { - if let Err(e) = finish_revalidation_request_tx.send(()).await { - tracing::trace!( + if let Err(error) = finish_revalidation_request_tx.send(()).await { + trace!( target: LOG_TARGET, at_hash = ?self.at.hash, - error = ?e, + %error, "view::finish_revalidation: sending cancellation request failed" ); } @@ -483,7 +484,7 @@ where ); }); - tracing::debug!( + debug!( target: LOG_TARGET, invalid = revalidation_result.invalid_hashes.len(), revalidated = revalidated_len, diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs index 1bb8f54bd10f..c4209a7d7f41 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view_store.rs @@ -42,6 +42,7 @@ use std::{ sync::Arc, time::Instant, }; +use tracing::{trace, warn}; /// Helper struct to maintain the context for pending transaction submission, executed for /// newly inserted views. @@ -259,7 +260,7 @@ where match result { Some(Err(error)) => { - tracing::trace!( + trace!( target: LOG_TARGET, ?tx_hash, %error, @@ -320,7 +321,7 @@ where match result { Some(Err(error)) => { - tracing::trace!( + trace!( target: LOG_TARGET, ?tx_hash, %error, @@ -432,7 +433,7 @@ where finalized_hash: Block::Hash, tree_route: &[Block::Hash], ) -> Vec> { - tracing::trace!( + trace!( target: LOG_TARGET, ?finalized_hash, ?tree_route, @@ -446,7 +447,7 @@ where .block_body(*block) .await .unwrap_or_else(|error| { - tracing::warn!( + warn!( target: LOG_TARGET, %error, "Finalize route: error request" @@ -518,10 +519,10 @@ where active_views.insert(view.at.hash, view.clone()); most_recent_view_lock.replace(view.at.hash); }; - tracing::trace!( + trace!( target: LOG_TARGET, inactive_views = ?self.inactive_views.read().keys(), - "insert_new_view: inactive_views" + "insert_new_view" ); } @@ -579,7 +580,7 @@ where .for_each(drop); } - tracing::trace!( + trace!( target: LOG_TARGET, ?removed_views, "handle_pre_finalized" @@ -638,14 +639,14 @@ where retain }); - tracing::trace!( + trace!( target: LOG_TARGET, inactive_views = ?inactive_views.keys(), "handle_finalized" ); } - tracing::trace!( + trace!( target: LOG_TARGET, ?dropped_views, "handle_finalized" @@ -680,9 +681,9 @@ where .collect::>() }; futures::future::join_all(finish_revalidation_futures).await; - tracing::trace!( + trace!( target: LOG_TARGET, - took = ?start.elapsed(), + duration = ?start.elapsed(), "finish_background_revalidations" ); } @@ -716,16 +717,16 @@ where return }; - let xt_hash = self.api.hash_and_length(&xt).0; - tracing::trace!( + let tx_hash = self.api.hash_and_length(&xt).0; + trace!( target: LOG_TARGET, ?replaced, - ?xt_hash, + ?tx_hash, watched, "replace_transaction" ); - self.replace_transaction_in_views(source, xt, xt_hash, replaced, watched).await; + self.replace_transaction_in_views(source, xt, tx_hash, replaced, watched).await; if let Some(replacement) = self.pending_txs_tasks.write().get_mut(&replaced) { replacement.mark_processed(); @@ -766,22 +767,22 @@ where view: Arc>, source: TimedTransactionSource, xt: ExtrinsicFor, - xt_hash: ExtrinsicHash, + tx_hash: ExtrinsicHash, watched: bool, ) { if watched { match view.submit_and_watch(source, xt).await { Ok(mut result) => { self.listener.add_view_watcher_for_tx( - xt_hash, + tx_hash, view.at.hash, result.expect_watcher().into_stream().boxed(), ); }, Err(error) => { - tracing::trace!( + trace!( target: LOG_TARGET, - ?xt_hash, + ?tx_hash, at_hash = ?view.at.hash, %error, "replace_transaction: submit_and_watch failed" @@ -790,9 +791,9 @@ where } } else { if let Some(Err(error)) = view.submit_many(std::iter::once((source, xt))).await.pop() { - tracing::trace!( + trace!( target: LOG_TARGET, - ?xt_hash, + ?tx_hash, at_hash = ?view.at.hash, %error, "replace_transaction: submit failed" @@ -809,14 +810,14 @@ where &self, source: TimedTransactionSource, xt: ExtrinsicFor, - xt_hash: ExtrinsicHash, + tx_hash: ExtrinsicHash, replaced: ExtrinsicHash, watched: bool, ) { - if watched && !self.listener.contains_tx(&xt_hash) { - tracing::trace!( + if watched && !self.listener.contains_tx(&tx_hash) { + trace!( target: LOG_TARGET, - ?xt_hash, + ?tx_hash, "error: replace_transaction_in_views: no listener for watched transaction" ); return; @@ -834,7 +835,7 @@ where view.clone(), source.clone(), xt.clone(), - xt_hash, + tx_hash, watched, ) }) From 442ccf5843632e186f8229d2785254a36495f401 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Wed, 29 Jan 2025 16:55:42 +0100 Subject: [PATCH 12/15] header fmt --- .../client/transaction-pool/src/common/tracing_log_xt.rs | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs index f4cd8462a07c..4d1c5d09cc7a 100644 --- a/substrate/client/transaction-pool/src/common/tracing_log_xt.rs +++ b/substrate/client/transaction-pool/src/common/tracing_log_xt.rs @@ -1,16 +1,21 @@ // This file is part of Substrate. + // Copyright (C) Parity Technologies (UK) Ltd. // SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0 + // This program is free software: you can redistribute it and/or modify // it under the terms of the GNU General Public License as published by // the Free Software Foundation, either version 3 of the License, or // (at your option) any later version. + // This program is distributed in the hope that it will be useful, // but WITHOUT ANY WARRANTY; without even the implied warranty of // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the // GNU General Public License for more details. + // You should have received a copy of the GNU General Public License // along with this program. If not, see . + //! Utility for logging transaction collections with tracing crate. /// Logs every transaction from given `tx_collection` with given level. From 01bb8ed51018891fda9e5ce56e3974bc17a988c9 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Wed, 29 Jan 2025 17:21:06 +0100 Subject: [PATCH 13/15] nit --- substrate/client/transaction-pool/src/fork_aware_txpool/view.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index 88e5809cc8a5..6f795cdeede6 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -489,7 +489,7 @@ where invalid = revalidation_result.invalid_hashes.len(), revalidated = revalidated_len, at_hash = ?self.at.hash, - took = ?start.elapsed(), + duration = ?start.elapsed(), "view::finish_revalidation: applying revalidation result" ); } From d6615a4c8805c9bf883b559f548d33107134c954 Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Wed, 29 Jan 2025 17:31:19 +0100 Subject: [PATCH 14/15] nit --- .../transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs index f2b019fc8bce..440e77313d3e 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/tx_mem_pool.rs @@ -495,10 +495,10 @@ where /// Removes a transaction with given hash from the memory pool. pub(super) fn remove_transaction( &self, - hash: &ExtrinsicHash, + tx_hash: &ExtrinsicHash, ) -> Option>> { - debug!(target: LOG_TARGET, ?hash, "mempool::remove_transaction"); - self.transactions.write().remove(hash) + debug!(target: LOG_TARGET, ?tx_hash, "mempool::remove_transaction"); + self.transactions.write().remove(tx_hash) } /// Revalidates a batch of transactions against the provided finalized block. From 1de8585b524ad61fbc05c4f6158656a51db1224c Mon Sep 17 00:00:00 2001 From: dharjeezy Date: Thu, 30 Jan 2025 11:50:26 +0100 Subject: [PATCH 15/15] nit --- .../src/fork_aware_txpool/fork_aware_txpool.rs | 14 +++++++------- .../transaction-pool/src/fork_aware_txpool/view.rs | 3 +-- 2 files changed, 8 insertions(+), 9 deletions(-) diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs index 594f5e85230e..c609ee2da22e 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/fork_aware_txpool.rs @@ -542,7 +542,7 @@ where debug!( target: LOG_TARGET, ?at, - allowed_delay = ?timeout, + ?timeout, "fatp::ready_at_with_timeout" ); let timeout = futures_timer::Delay::new(timeout); @@ -687,7 +687,7 @@ where debug!( target: LOG_TARGET, count = xts.len(), - views = self.active_views_count(), + active_views_count = self.active_views_count(), "fatp::submit_at" ); log_xt_trace!(target: LOG_TARGET, xts.iter().map(|xt| self.tx_hash(xt)), "fatp::submit_at"); @@ -784,7 +784,7 @@ where trace!( target: LOG_TARGET, tx_hash = ?self.tx_hash(&xt), - views = self.active_views_count(), + active_views_count = self.active_views_count(), "fatp::submit_one" ); match self.submit_at(_at, source, vec![xt]).await { @@ -894,7 +894,7 @@ where trace!( target: LOG_TARGET, ?tx_hash, - result_is_some = result.is_some(), + is_ready = result.is_some(), ?most_recent_view, "ready_transaction" ); @@ -954,7 +954,7 @@ where ) -> Result { debug!( target: LOG_TARGET, - views = self.active_views_count(), + active_views_count = self.active_views_count(), "fatp::submit_local" ); let xt = Arc::from(xt); @@ -1402,7 +1402,7 @@ where target: LOG_TARGET, ?finalized_number, ?tree_route, - views_count = self.active_views_count(), + active_views_count = self.active_views_count(), "handle_finalized" ); let finalized_xts = self.view_store.handle_finalized(finalized_hash, tree_route).await; @@ -1431,7 +1431,7 @@ where self.ready_poll.lock().remove_cancelled(); trace!( target: LOG_TARGET, - views_count = self.active_views_count(), + active_views_count = self.active_views_count(), "handle_finalized after" ); } diff --git a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs index 6f795cdeede6..6324997da67b 100644 --- a/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs +++ b/substrate/client/transaction-pool/src/fork_aware_txpool/view.rs @@ -328,8 +328,7 @@ where duration = ?revalidation_duration, "view::revalidate" ); - log_xt_trace!(data:tuple, target:LOG_TARGET, validation_results.iter().map(|x| (x.1, &x.0)), "view::revalidateresult: {:?}"); - + log_xt_trace!(data:tuple, target:LOG_TARGET, validation_results.iter().map(|x| (x.1, &x.0)), "view::revalidate result: {:?}"); for (validation_result, tx_hash, tx) in validation_results { match validation_result { Ok(Err(TransactionValidityError::Invalid(_))) => {