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,