txpool: use tracing for structured logging

prdoc/pr_8001.prdoc

@@ -0,0 +1,7 @@
+title: 'Structured Logging for transaction pool'
+doc:
+- audience: Node Dev
+  description: Replacement of log crate with tracing crate for structured logging in transaction pool.
+crates:
+- name: sc-transaction-pool
+  bump: minor

substrate/client/transaction-pool/Cargo.toml

@@ -27,7 +27,6 @@ futures-timer = { workspace = true }
 indexmap = { workspace = true }
 itertools = { workspace = true }
 linked-hash-map = { workspace = true }
-log = { workspace = true, default-features = true }
 parking_lot = { workspace = true, default-features = true }
 prometheus-endpoint = { workspace = true, default-features = true }
 sc-client-api = { workspace = true, default-features = true }

substrate/client/transaction-pool/src/builder.rs

@@ -224,7 +224,13 @@ where
 
 	/// Creates an instance of transaction pool.
 	pub fn build(self) -> TransactionPoolHandle<Block, Client> {
-		log::info!(target:LOG_TARGET, " creating {:?} txpool {:?}/{:?}.", self.options.txpool_type, self.options.options.ready, self.options.options.future);
+		tracing::info!(
+			target: LOG_TARGET,
+			txpool_type = ?self.options.txpool_type,
+			ready = ?self.options.options.ready,
+			future = ?self.options.options.future,
+			"Creating transaction pool"
+		);
 		TransactionPoolWrapper::<Block, Client>(match self.options.txpool_type {
 			TransactionPoolType::SingleState => Box::new(SingleStateFullPool::new_full(
 				self.options.options,

substrate/client/transaction-pool/src/common/api.rs

@@ -45,6 +45,7 @@ use super::{
 	metrics::{ApiMetrics, ApiMetricsExt},
 };
 use crate::graph;
+use tracing::{trace, warn};
 
 /// The transaction pool logic for full client.
 pub struct FullChainApi<Client, Block> {
@@ -84,11 +85,11 @@ impl<Client, Block> FullChainApi<Client, Block> {
 		spawner: &impl SpawnEssentialNamed,
 	) -> Self {
 		let metrics = prometheus.map(ApiMetrics::register).and_then(|r| match r {
-			Err(err) => {
-				log::warn!(
+			Err(error) => {
+				warn!(
 					target: LOG_TARGET,
-					"Failed to register transaction pool api prometheus metrics: {:?}",
-					err,
+					?error,
+					"Failed to register transaction pool API Prometheus metrics"
 				);
 				None
 			},
@@ -230,7 +231,7 @@ where
 	Client::Api: TaggedTransactionQueue<Block>,
 {
 	let s = std::time::Instant::now();
-	let h = uxt.using_encoded(|x| <traits::HashingFor<Block> as traits::Hash>::hash(x));
+	let tx_hash = uxt.using_encoded(|x| <traits::HashingFor<Block> as traits::Hash>::hash(x));
 
 	let result = sp_tracing::within_span!(sp_tracing::Level::TRACE, "validate_transaction";
 	{
@@ -280,7 +281,12 @@ where
 			}
 		})
 	});
-	log::trace!(target: LOG_TARGET, "[{h:?}] validate_transaction_blocking: at:{at:?} took:{:?}", s.elapsed());
-
+	trace!(
+		target: LOG_TARGET,
+		?tx_hash,
+		?at,
+		duration = ?s.elapsed(),
+		"validate_transaction_blocking"
+	);
 	result
 }

substrate/client/transaction-pool/src/common/enactment_state.rs

@@ -22,6 +22,7 @@ use crate::LOG_TARGET;
 use sc_transaction_pool_api::ChainEvent;
 use sp_blockchain::TreeRoute;
 use sp_runtime::traits::{Block as BlockT, NumberFor, Saturating};
+use tracing::{debug, trace};
 
 /// The threshold since the last update where we will skip any maintenance for blocks.
 ///
@@ -112,40 +113,40 @@ where
 			};
 
 		if skip_maintenance {
-			log::trace!(target: LOG_TARGET, "skip maintain: tree_route would be too long");
+			debug!(target: LOG_TARGET, "skip maintain: tree_route would be too long");
 			self.force_update(event);
 			return Ok(EnactmentAction::Skip)
 		}
 
 		// block was already finalized
 		if self.recent_finalized_block == new_hash {
-			log::trace!(target: LOG_TARGET, "handle_enactment: block already finalized");
+			trace!(target: LOG_TARGET, "handle_enactment: block already finalized");
 			return Ok(EnactmentAction::Skip)
 		}
 
 		// compute actual tree route from best_block to notified block, and use
 		// it instead of tree_route provided with event
 		let tree_route = tree_route(self.recent_best_block, new_hash)?;
-
-		log::trace!(
+		trace!(
 			target: LOG_TARGET,
-			"resolve hash: {new_hash:?} finalized: {finalized:?} \
-			 tree_route: (common {:?}, last {:?}) best_block: {:?} finalized_block:{:?}",
-			tree_route.common_block(),
-			tree_route.last(),
-			self.recent_best_block,
-			self.recent_finalized_block
+			?new_hash,
+			?finalized,
+			common_block = ?tree_route.common_block(),
+			last_block = ?tree_route.last(),
+			best_block = ?self.recent_best_block,
+			finalized_block = ?self.recent_finalized_block,
+			"resolve hash"
 		);
 
 		// check if recently finalized block is on retracted path. this could be
 		// happening if we first received a finalization event and then a new
 		// best event for some old stale best head.
 		if tree_route.retracted().iter().any(|x| x.hash == self.recent_finalized_block) {
-			log::trace!(
+			trace!(
 				target: LOG_TARGET,
-				"Recently finalized block {} would be retracted by ChainEvent {}, skipping",
-				self.recent_finalized_block,
-				new_hash
+				recent_finalized_block = ?self.recent_finalized_block,
+				?new_hash,
+				"Recently finalized block would be retracted by ChainEvent, skipping"
 			);
 			return Ok(EnactmentAction::Skip)
 		}
@@ -158,10 +159,7 @@ where
 			// case also covers best_block == new_hash), recent_best_block
 			// remains valid.
 			if tree_route.enacted().is_empty() {
-				log::trace!(
-					target: LOG_TARGET,
-					"handle_enactment: no newly enacted blocks since recent best block"
-				);
+				trace!(target: LOG_TARGET, "handle_enactment: no newly enacted blocks since recent best block");
 				return Ok(EnactmentAction::HandleFinalization)
 			}
 
@@ -180,11 +178,11 @@ where
 			ChainEvent::NewBestBlock { hash, .. } => self.recent_best_block = *hash,
 			ChainEvent::Finalized { hash, .. } => self.recent_finalized_block = *hash,
 		};
-		log::trace!(
+		trace!(
 			target: LOG_TARGET,
-			"forced update: {:?}, {:?}",
-			self.recent_best_block,
-			self.recent_finalized_block,
+			recent_best_block = ?self.recent_best_block,
+			recent_finalized_block = ?self.recent_finalized_block,
+			"forced update"
 		);
 	}
 }

substrate/client/transaction-pool/src/common/metrics.rs

@@ -48,8 +48,12 @@ impl<M: MetricsRegistrant> GenericMetricsLink<M> {
 	pub fn new(registry: Option<&Registry>) -> Self {
 		Self(Arc::new(registry.and_then(|registry| {
 			M::register(registry)
-				.map_err(|err| {
-					log::warn!(target: LOG_TARGET, "Failed to register prometheus metrics: {}", err);
+				.map_err(|error| {
+					tracing::warn!(
+						target: LOG_TARGET,
+						%error,
+						"Failed to register prometheus metrics"
+					);
 				})
 				.ok()
 		})))

substrate/client/transaction-pool/src/common/mod.rs

@@ -21,7 +21,6 @@
 pub(crate) mod api;
 pub(crate) mod enactment_state;
 pub(crate) mod error;
-pub(crate) mod log_xt;
 pub(crate) mod metrics;
 #[cfg(test)]
 pub(crate) mod tests;

substrate/client/transaction-pool/src/graph/base_pool.rs

@@ -23,7 +23,6 @@
 use std::{cmp::Ordering, collections::HashSet, fmt, hash, sync::Arc, time::Instant};
 
 use crate::LOG_TARGET;
-use log::{trace, warn};
 use sc_transaction_pool_api::{error, InPoolTransaction, PoolStatus};
 use serde::Serialize;
 use sp_core::hexdisplay::HexDisplay;
@@ -34,6 +33,7 @@ use sp_runtime::{
 		TransactionTag as Tag,
 	},
 };
+use tracing::{trace, warn};
 
 use super::{
 	future::{FutureTransactions, WaitingTransaction},
@@ -318,10 +318,10 @@ impl<Hash: hash::Hash + Member + Serialize, Ex: std::fmt::Debug> BasePool<Hash,
 		let tx = WaitingTransaction::new(tx, self.ready.provided_tags(), &self.recently_pruned);
 		trace!(
 			target: LOG_TARGET,
-			"[{:?}] Importing {:?} to {}",
-			tx.transaction.hash,
-			tx,
-			if tx.is_ready() { "ready" } else { "future" }
+			tx_hash = ?tx.transaction.hash,
+			?tx,
+			set = if tx.is_ready() { "ready" } else { "future" },
+			"Importing transaction"
 		);
 
 		// If all tags are not satisfied import to future.
@@ -345,7 +345,7 @@ impl<Hash: hash::Hash + Member + Serialize, Ex: std::fmt::Debug> BasePool<Hash,
 		&mut self,
 		tx: WaitingTransaction<Hash, Ex>,
 	) -> error::Result<Imported<Hash, Ex>> {
-		let hash = tx.transaction.hash.clone();
+		let tx_hash = tx.transaction.hash.clone();
 		let mut promoted = vec![];
 		let mut failed = vec![];
 		let mut removed = vec![];
@@ -373,24 +373,36 @@ impl<Hash: hash::Hash + Member + Serialize, Ex: std::fmt::Debug> BasePool<Hash,
 					// re-import them.
 					removed.append(&mut replaced);
 				},
-				Err(e @ error::Error::TooLowPriority { .. }) =>
+				Err(error @ error::Error::TooLowPriority { .. }) => {
+					trace!(
+						target: LOG_TARGET,
+						tx_hash = ?current_tx.hash,
+						?first,
+						%error,
+						"Error importing transaction"
+					);
 					if first {
-						trace!(target: LOG_TARGET, "[{:?}] Error importing {first}: {:?}", current_tx.hash, e);
-						return Err(e)
+						return Err(error)
 					} else {
-						trace!(target: LOG_TARGET, "[{:?}] Error importing {first}: {:?}", current_tx.hash, e);
 						removed.push(current_tx);
 						promoted.retain(|hash| *hash != current_hash);
-					},
+					}
+				},
 				// transaction failed to be imported.
-				Err(e) =>
+				Err(error) => {
+					trace!(
+						target: LOG_TARGET,
+						tx_hash = ?current_tx.hash,
+						?error,
+						first,
+						"Error importing transaction"
+					);
 					if first {
-						trace!(target: LOG_TARGET, "[{:?}] Error importing {first}: {:?}", current_tx.hash, e);
-						return Err(e)
+						return Err(error)
 					} else {
-						trace!(target: LOG_TARGET, "[{:?}] Error importing {first}: {:?}", current_tx.hash, e);
 						failed.push(current_tx.hash.clone());
-					},
+					}
+				},
 			}
 			first = false;
 		}
@@ -400,16 +412,20 @@ impl<Hash: hash::Hash + Member + Serialize, Ex: std::fmt::Debug> BasePool<Hash,
 		// future transactions pushed out current transaction.
 		// This means that there is a cycle and the transactions should
 		// be moved back to future, since we can't resolve it.
-		if removed.iter().any(|tx| tx.hash == hash) {
+		if removed.iter().any(|tx| tx.hash == tx_hash) {
 			// We still need to remove all transactions that we promoted
 			// since they depend on each other and will never get to the best iterator.
 			self.ready.remove_subtree(&promoted);
 
-			trace!(target: LOG_TARGET, "[{:?}] Cycle detected, bailing.", hash);
+			trace!(
+				target: LOG_TARGET,
+				?tx_hash,
+				"Cycle detected, bailing."
+			);
 			return Err(error::Error::CycleDetected)
 		}
 
-		Ok(Imported::Ready { hash, promoted, failed, removed })
+		Ok(Imported::Ready { hash: tx_hash, promoted, failed, removed })
 	}
 
 	/// Returns an iterator over ready transactions in the pool.
@@ -569,15 +585,17 @@ impl<Hash: hash::Hash + Member + Serialize, Ex: std::fmt::Debug> BasePool<Hash,
 		}
 
 		for tx in to_import {
-			let hash = tx.transaction.hash.clone();
+			let tx_hash = tx.transaction.hash.clone();
 			match self.import_to_ready(tx) {
 				Ok(res) => promoted.push(res),
-				Err(e) => {
+				Err(error) => {
 					warn!(
 						target: LOG_TARGET,
-						"[{:?}] Failed to promote during pruning: {:?}", hash, e,
+						?tx_hash,
+						?error,
+						"Failed to promote during pruning."
 					);
-					failed.push(hash)
+					failed.push(tx_hash)
 				},
 			}
 		}