xcm-executor: Improve logging (paritytech#4996)

This improves logging in the xcm-executor to have better debugability
when executing a XCM message.

Author: bkchr

Cargo.lock

@@ -22,7 +22,7 @@ sp-core = { workspace = true }
 sp-runtime = { workspace = true }
 sp-weights = { workspace = true }
 frame-support = { workspace = true }
-log = { workspace = true }
+tracing = { workspace = true }
 frame-benchmarking = { optional = true, workspace = true }
 
 [features]
@@ -37,13 +37,13 @@ std = [
 	"environmental/std",
 	"frame-benchmarking/std",
 	"frame-support/std",
-	"log/std",
 	"scale-info/std",
 	"sp-arithmetic/std",
 	"sp-core/std",
 	"sp-io/std",
 	"sp-runtime/std",
 	"sp-std/std",
 	"sp-weights/std",
+	"tracing/std",
 	"xcm/std",
 ]

polkadot/xcm/xcm-executor/Cargo.toml

@@ -208,9 +208,12 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
 		weight_credit: Weight,
 	) -> Outcome {
 		let origin = origin.into();
-		log::trace!(
+		tracing::trace!(
 			target: "xcm::execute",
-			"origin: {origin:?}, message: {message:?}, weight_credit: {weight_credit:?}",
+			?origin,
+			?message,
+			?weight_credit,
+			"Executing message",
 		);
 		let mut properties = Properties { weight_credit, message_id: None };
 
@@ -226,10 +229,13 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
 			xcm_weight,
 			&mut properties,
 		) {
-			log::trace!(
+			tracing::trace!(
 				target: "xcm::execute",
-				"Barrier blocked execution! Error: {e:?}. \
-				 (origin: {origin:?}, message: {message:?}, properties: {properties:?})",
+				?origin,
+				?message,
+				?properties,
+				error = ?e,
+				"Barrier blocked execution",
 			);
 			return Outcome::Error { error: XcmError::Barrier }
 		}
@@ -240,7 +246,7 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
 
 		while !message.0.is_empty() {
 			let result = vm.process(message);
-			log::trace!(target: "xcm::execute", "result: {result:?}");
+			tracing::trace!(target: "xcm::execute", ?result, "Message executed");
 			message = if let Err(error) = result {
 				vm.total_surplus.saturating_accrue(error.weight);
 				vm.error = Some((error.index, error.xcm_error));
@@ -282,11 +288,11 @@ pub struct ExecutorError {
 #[cfg(feature = "runtime-benchmarks")]
 impl From<ExecutorError> for frame_benchmarking::BenchmarkError {
 	fn from(error: ExecutorError) -> Self {
-		log::error!(
-			"XCM ERROR >> Index: {:?}, Error: {:?}, Weight: {:?}",
-			error.index,
-			error.xcm_error,
-			error.weight
+		tracing::error!(
+			index = ?error.index,
+			xcm_error = ?error.xcm_error,
+			weight = ?error.weight,
+			"XCM ERROR",
 		);
 		Self::Stop("xcm executor error: see error logs")
 	}
@@ -326,10 +332,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		let mut weight_used = xcm_weight.saturating_sub(self.total_surplus);
 
 		if !self.holding.is_empty() {
-			log::trace!(
+			tracing::trace!(
 				target: "xcm::post_process",
-				"Trapping assets in holding register: {:?}, context: {:?} (original_origin: {:?})",
-				self.holding, self.context, self.original_origin,
+				holding_register = ?self.holding,
+				context = ?self.context,
+				original_origin = ?self.original_origin,
+				"Trapping assets in holding register",
 			);
 			let effective_origin = self.context.origin.as_ref().unwrap_or(&self.original_origin);
 			let trap_weight =
@@ -342,7 +350,13 @@ impl<Config: config::Config> XcmExecutor<Config> {
 			// TODO: #2841 #REALWEIGHT We should deduct the cost of any instructions following
 			// the error which didn't end up being executed.
 			Some((_i, e)) => {
-				log::trace!(target: "xcm::post_process", "Execution errored at {:?}: {:?} (original_origin: {:?})", _i, e, self.original_origin);
+				tracing::trace!(
+					target: "xcm::post_process",
+					instruction = ?_i,
+					error = ?e,
+					original_origin = ?self.original_origin,
+					"Execution failed",
+				);
 				Outcome::Incomplete { used: weight_used, error: e }
 			},
 		}
@@ -363,8 +377,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		msg: Xcm<()>,
 		reason: FeeReason,
 	) -> Result<XcmHash, XcmError> {
-		log::trace!(
-			target: "xcm::send", "Sending msg: {msg:?}, to destination: {dest:?}, (reason: {reason:?})"
+		tracing::trace!(
+			target: "xcm::send",
+			?msg,
+			destination = ?dest,
+			reason = ?reason,
+			"Sending msg",
 		);
 		let (ticket, fee) = validate_send::<Config::XcmSender>(dest, msg)?;
 		self.take_fee(fee, reason)?;
@@ -400,20 +418,25 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		// `holding_limit` items (which has a best case outcome of holding.len() == holding_limit),
 		// then the operation is guaranteed to succeed.
 		let worst_case_holding_len = self.holding.len() + assets_length;
-		log::trace!(target: "xcm::ensure_can_subsume_assets", "worst_case_holding_len: {:?}, holding_limit: {:?}", worst_case_holding_len, self.holding_limit);
+		tracing::trace!(
+			target: "xcm::ensure_can_subsume_assets",
+			?worst_case_holding_len,
+			holding_limit = ?self.holding_limit,
+			"Ensuring subsume assets work",
+		);
 		ensure!(worst_case_holding_len <= self.holding_limit * 2, XcmError::HoldingWouldOverflow);
 		Ok(())
 	}
 
 	/// Refund any unused weight.
 	fn refund_surplus(&mut self) -> Result<(), XcmError> {
 		let current_surplus = self.total_surplus.saturating_sub(self.total_refunded);
-		log::trace!(
+		tracing::trace!(
 			target: "xcm::refund_surplus",
-			"total_surplus: {:?}, total_refunded: {:?}, current_surplus: {:?}",
-			self.total_surplus,
-			self.total_refunded,
-			current_surplus,
+			total_surplus = ?self.total_surplus,
+			total_refunded = ?self.total_refunded,
+			?current_surplus,
+			"Refunding surplus",
 		);
 		if current_surplus.any_gt(Weight::zero()) {
 			if let Some(w) = self.trader.refund_weight(current_surplus, &self.context) {
@@ -426,7 +449,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
 						.defensive_proof(
 							"refund_weight returned an asset capable of buying weight; qed",
 						);
-					log::error!(
+					tracing::error!(
 						target: "xcm::refund_surplus",
 						"error: HoldingWouldOverflow",
 					);
@@ -436,10 +459,9 @@ impl<Config: config::Config> XcmExecutor<Config> {
 				self.holding.subsume_assets(w.into());
 			}
 		}
-		log::trace!(
+		tracing::trace!(
 			target: "xcm::refund_surplus",
-			"total_refunded: {:?}",
-			self.total_refunded,
+			total_refunded = ?self.total_refunded,
 		);
 		Ok(())
 	}
@@ -448,13 +470,13 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		if Config::FeeManager::is_waived(self.origin_ref(), reason.clone()) {
 			return Ok(())
 		}
-		log::trace!(
+		tracing::trace!(
 			target: "xcm::fees",
-			"taking fee: {:?} from origin_ref: {:?} in fees_mode: {:?} for a reason: {:?}",
-			fee,
-			self.origin_ref(),
-			self.fees_mode,
-			reason,
+			?fee,
+			origin_ref = ?self.origin_ref(),
+			fees_mode = ?self.fees_mode,
+			?reason,
+			"Taking fees",
 		);
 		let paid = if self.fees_mode.jit_withdraw {
 			let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?;
@@ -507,7 +529,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		let reanchor_context = Config::UniversalLocation::get();
 		let reanchored =
 			reanchorable.reanchored(&destination, &reanchor_context).map_err(|error| {
-				log::error!(target: "xcm::reanchor", "Failed reanchoring with error {error:?}");
+				tracing::error!(target: "xcm::reanchor", ?error, "Failed reanchoring with error");
 				XcmError::ReanchorFailed
 			})?;
 		Ok((reanchored, reanchor_context))
@@ -530,13 +552,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
 	}
 
 	fn process(&mut self, xcm: Xcm<Config::RuntimeCall>) -> Result<(), ExecutorError> {
-		log::trace!(
+		tracing::trace!(
 			target: "xcm::process",
-			"origin: {:?}, total_surplus/refunded: {:?}/{:?}, error_handler_weight: {:?}",
-			self.origin_ref(),
-			self.total_surplus,
-			self.total_refunded,
-			self.error_handler_weight,
+			origin = ?self.origin_ref(),
+			total_surplus = ?self.total_surplus,
+			total_refunded = ?self.total_refunded,
+			error_handler_weight = ?self.error_handler_weight,
 		);
 		let mut result = Ok(());
 		for (i, instr) in xcm.0.into_iter().enumerate() {
@@ -566,7 +587,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
 						self.process_instruction(instr)
 					});
 					if let Err(e) = inst_res {
-						log::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e);
+						tracing::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e);
 						*r = Err(ExecutorError {
 							index: i as u32,
 							xcm_error: e,
@@ -588,11 +609,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		&mut self,
 		instr: Instruction<Config::RuntimeCall>,
 	) -> Result<(), XcmError> {
-		log::trace!(
+		tracing::trace!(
 			target: "xcm::process_instruction",
-			"=== {:?}",
-			instr
+			instruction = ?instr,
+			"Processing instruction",
 		);
+
 		match instr {
 			WithdrawAsset(assets) => {
 				let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?;
@@ -694,7 +716,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
 			Transact { origin_kind, require_weight_at_most, mut call } => {
 				// We assume that the Relay-chain is allowed to use transact on this parachain.
 				let origin = self.cloned_origin().ok_or_else(|| {
-					log::trace!(
+					tracing::trace!(
 						target: "xcm::process_instruction::transact",
 						"No origin provided",
 					);
@@ -704,21 +726,22 @@ impl<Config: config::Config> XcmExecutor<Config> {
 
 				// TODO: #2841 #TRANSACTFILTER allow the trait to issue filters for the relay-chain
 				let message_call = call.take_decoded().map_err(|_| {
-					log::trace!(
+					tracing::trace!(
 						target: "xcm::process_instruction::transact",
 						"Failed to decode call",
 					);
 
 					XcmError::FailedToDecode
 				})?;
 
-				log::trace!(
+				tracing::trace!(
 					target: "xcm::process_instruction::transact",
-					"Processing call: {message_call:?}",
+					?call,
+					"Processing call",
 				);
 
 				if !Config::SafeCallFilter::contains(&message_call) {
-					log::trace!(
+					tracing::trace!(
 						target: "xcm::process_instruction::transact",
 						"Call filtered by `SafeCallFilter`",
 					);
@@ -729,26 +752,31 @@ impl<Config: config::Config> XcmExecutor<Config> {
 				let dispatch_origin =
 					Config::OriginConverter::convert_origin(origin.clone(), origin_kind).map_err(
 						|_| {
-							log::trace!(
+							tracing::trace!(
 								target: "xcm::process_instruction::transact",
-								"Failed to convert origin {origin:?} and origin kind {origin_kind:?} to a local origin."
+								?origin,
+								?origin_kind,
+								"Failed to convert origin to a local origin."
 							);
 
 							XcmError::BadOrigin
 						},
 					)?;
 
-				log::trace!(
+				tracing::trace!(
 					target: "xcm::process_instruction::transact",
-					"Dispatching with origin: {dispatch_origin:?}",
+					origin = ?dispatch_origin,
+					"Dispatching with origin",
 				);
 
 				let weight = message_call.get_dispatch_info().weight;
 
 				if !weight.all_lte(require_weight_at_most) {
-					log::trace!(
+					tracing::trace!(
 						target: "xcm::process_instruction::transact",
-						"Max {weight} bigger than require at most {require_weight_at_most}",
+						%weight,
+						%require_weight_at_most,
+						"Max weight bigger than require at most",
 					);
 
 					return Err(XcmError::MaxWeightInvalid)
@@ -757,17 +785,19 @@ impl<Config: config::Config> XcmExecutor<Config> {
 				let maybe_actual_weight =
 					match Config::CallDispatcher::dispatch(message_call, dispatch_origin) {
 						Ok(post_info) => {
-							log::trace!(
+							tracing::trace!(
 								target: "xcm::process_instruction::transact",
-								"Dispatch successful: {post_info:?}"
+								?post_info,
+								"Dispatch successful"
 							);
 							self.transact_status = MaybeErrorCode::Success;
 							post_info.actual_weight
 						},
 						Err(error_and_info) => {
-							log::trace!(
+							tracing::trace!(
 								target: "xcm::process_instruction::transact",
-								"Dispatch failed {error_and_info:?}"
+								?error_and_info,
+								"Dispatch failed"
 							);
 
 							self.transact_status = error_and_info.error.encode().into();