xcm: Improve debuggability (#2799)

Adds more logging to the XCM execution for better debugging.

Cargo.lock

@@ -19143,6 +19143,7 @@ version = "1.0.0"
 name = "staging-xcm"
 version = "1.0.0"
 dependencies = [
+ "array-bytes 6.1.0",
  "bounded-collections",
  "derivative",
  "environmental",

cumulus/parachains/runtimes/coretime/coretime-rococo/src/lib.rs

@@ -121,7 +121,7 @@ pub const VERSION: RuntimeVersion = RuntimeVersion {
 	spec_name: create_runtime_str!("coretime-rococo"),
 	impl_name: create_runtime_str!("coretime-rococo"),
 	authoring_version: 1,
-	spec_version: 1_005_002,
+	spec_version: 1_005_003,
 	impl_version: 0,
 	apis: RUNTIME_API_VERSIONS,
 	transaction_version: 0,

polkadot/xcm/Cargo.toml

@@ -10,6 +10,7 @@ license.workspace = true
 workspace = true
 
 [dependencies]
+array-bytes = "6.1"
 bounded-collections = { version = "0.1.9", default-features = false, features = ["serde"] }
 derivative = { version = "2.2.0", default-features = false, features = ["use_core"] }
 impl-trait-for-tuples = "0.2.2"

polkadot/xcm/src/double_encoded.rs

@@ -47,7 +47,7 @@ impl<T> Eq for DoubleEncoded<T> {}
 
 impl<T> core::fmt::Debug for DoubleEncoded<T> {
 	fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result {
-		self.encoded.fmt(f)
+		array_bytes::bytes2hex("0x", &self.encoded).fmt(f)
 	}
 }
 

polkadot/xcm/xcm-builder/src/process_xcm_message.rs

@@ -16,16 +16,15 @@
 
 //! Implementation of `ProcessMessage` for an `ExecuteXcm` implementation.
 
-use frame_support::{
-	ensure,
-	traits::{ProcessMessage, ProcessMessageError},
-};
+use frame_support::traits::{ProcessMessage, ProcessMessageError};
 use parity_scale_codec::{Decode, FullCodec, MaxEncodedLen};
 use scale_info::TypeInfo;
 use sp_std::{fmt::Debug, marker::PhantomData};
 use sp_weights::{Weight, WeightMeter};
 use xcm::prelude::*;
 
+const LOG_TARGET: &str = "xcm::process-message";
+
 /// A message processor that delegates execution to an `XcmExecutor`.
 pub struct ProcessXcmMessage<MessageOrigin, XcmExecutor, Call>(
 	PhantomData<(MessageOrigin, XcmExecutor, Call)>,
@@ -45,21 +44,68 @@ impl<
 		meter: &mut WeightMeter,
 		id: &mut XcmHash,
 	) -> Result<bool, ProcessMessageError> {
-		let versioned_message = VersionedXcm::<Call>::decode(&mut &message[..])
-			.map_err(|_| ProcessMessageError::Corrupt)?;
-		let message = Xcm::<Call>::try_from(versioned_message)
-			.map_err(|_| ProcessMessageError::Unsupported)?;
-		let pre = XcmExecutor::prepare(message).map_err(|_| ProcessMessageError::Unsupported)?;
+		let versioned_message = VersionedXcm::<Call>::decode(&mut &message[..]).map_err(|e| {
+			log::trace!(
+				target: LOG_TARGET,
+				"`VersionedXcm` failed to decode: {e:?}",
+			);
+
+			ProcessMessageError::Corrupt
+		})?;
+		let message = Xcm::<Call>::try_from(versioned_message).map_err(|_| {
+			log::trace!(
+				target: LOG_TARGET,
+				"Failed to convert `VersionedXcm` into `XcmV3`.",
+			);
+
+			ProcessMessageError::Unsupported
+		})?;
+		let pre = XcmExecutor::prepare(message).map_err(|_| {
+			log::trace!(
+				target: LOG_TARGET,
+				"Failed to prepare message.",
+			);
+
+			ProcessMessageError::Unsupported
+		})?;
 		// The worst-case weight:
 		let required = pre.weight_of();
-		ensure!(meter.can_consume(required), ProcessMessageError::Overweight(required));
+		if !meter.can_consume(required) {
+			log::trace!(
+				target: LOG_TARGET,
+				"Xcm required {required} more than remaining {}",
+				meter.remaining(),
+			);
+
+			return Err(ProcessMessageError::Overweight(required))
+		}
 
 		let (consumed, result) = match XcmExecutor::execute(origin.into(), pre, id, Weight::zero())
 		{
-			Outcome::Complete(w) => (w, Ok(true)),
-			Outcome::Incomplete(w, _) => (w, Ok(false)),
+			Outcome::Complete(w) => {
+				log::trace!(
+					target: LOG_TARGET,
+					"XCM message execution complete, used weight: {w}",
+				);
+				(w, Ok(true))
+			},
+			Outcome::Incomplete(w, e) => {
+				log::trace!(
+					target: LOG_TARGET,
+					"XCM message execution incomplete, used weight: {w}, error: {e:?}",
+				);
+
+				(w, Ok(false))
+			},
 			// In the error-case we assume the worst case and consume all possible weight.
-			Outcome::Error(_) => (required, Err(ProcessMessageError::Unsupported)),
+			Outcome::Error(e) => {
+				log::trace!(
+					target: LOG_TARGET,
+					"XCM message execution error: {e:?}",
+				);
+
+				(required, Err(ProcessMessageError::Unsupported))
+			},
 		};
 		meter.consume(consumed);
 		result

polkadot/xcm/xcm-builder/src/tests/mock.rs

@@ -48,6 +48,7 @@ pub use xcm_executor::{
 	Assets, Config,
 };
 
+#[derive(Debug)]
 pub enum TestOrigin {
 	Root,
 	Relay,

polkadot/xcm/xcm-executor/src/lib.rs

@@ -24,7 +24,7 @@ use frame_support::{
 use parity_scale_codec::{Decode, Encode};
 use sp_core::defer;
 use sp_io::hashing::blake2_128;
-use sp_std::{marker::PhantomData, prelude::*};
+use sp_std::{fmt::Debug, marker::PhantomData, prelude::*};
 use sp_weights::Weight;
 use xcm::latest::prelude::*;
 
@@ -199,10 +199,7 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
 		let origin = origin.into();
 		log::trace!(
 			target: "xcm::execute_xcm_in_credit",
-			"origin: {:?}, message: {:?}, weight_credit: {:?}",
-			origin,
-			message,
-			weight_credit,
+			"origin: {origin:?}, message: {message:?}, weight_credit: {weight_credit:?}",
 		);
 		let mut properties = Properties { weight_credit, message_id: None };
 		if let Err(e) = Config::Barrier::should_execute(
@@ -213,11 +210,8 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
 		) {
 			log::trace!(
 				target: "xcm::execute_xcm_in_credit",
-				"Barrier blocked execution! Error: {:?}. (origin: {:?}, message: {:?}, properties: {:?})",
-				e,
-				origin,
-				message,
-				properties,
+				"Barrier blocked execution! Error: {e:?}. \
+				 (origin: {origin:?}, message: {message:?}, properties: {properties:?})",
 			);
 			return Outcome::Error(XcmError::Barrier)
 		}
@@ -228,7 +222,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_xcm_in_credit", "result: {:?}", result);
+			log::trace!(target: "xcm::execute_xcm_in_credit", "result: {result:?}");
 			message = if let Err(error) = result {
 				vm.total_surplus.saturating_accrue(error.weight);
 				vm.error = Some((error.index, error.xcm_error));
@@ -302,65 +296,6 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		}
 	}
 
-	#[cfg(feature = "runtime-benchmarks")]
-	pub fn bench_process(&mut self, xcm: Xcm<Config::RuntimeCall>) -> Result<(), ExecutorError> {
-		self.process(xcm)
-	}
-
-	fn process(&mut self, xcm: Xcm<Config::RuntimeCall>) -> Result<(), ExecutorError> {
-		log::trace!(
-			target: "xcm::process",
-			"origin: {:?}, total_surplus/refunded: {:?}/{:?}, error_handler_weight: {:?}",
-			self.origin_ref(),
-			self.total_surplus,
-			self.total_refunded,
-			self.error_handler_weight,
-		);
-		let mut result = Ok(());
-		for (i, instr) in xcm.0.into_iter().enumerate() {
-			match &mut result {
-				r @ Ok(()) => {
-					// Initialize the recursion count only the first time we hit this code in our
-					// potential recursive execution.
-					let inst_res = recursion_count::using_once(&mut 1, || {
-						recursion_count::with(|count| {
-							if *count > RECURSION_LIMIT {
-								return Err(XcmError::ExceedsStackLimit)
-							}
-							*count = count.saturating_add(1);
-							Ok(())
-						})
-						// This should always return `Some`, but let's play it safe.
-						.unwrap_or(Ok(()))?;
-
-						// Ensure that we always decrement the counter whenever we finish processing
-						// the instruction.
-						defer! {
-							recursion_count::with(|count| {
-								*count = count.saturating_sub(1);
-							});
-						}
-
-						self.process_instruction(instr)
-					});
-					if let Err(e) = inst_res {
-						log::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e);
-						*r = Err(ExecutorError {
-							index: i as u32,
-							xcm_error: e,
-							weight: Weight::zero(),
-						});
-					}
-				},
-				Err(ref mut error) =>
-					if let Ok(x) = Config::Weigher::instr_weight(&instr) {
-						error.weight.saturating_accrue(x)
-					},
-			}
-		}
-		result
-	}
-
 	/// Execute any final operations after having executed the XCM message.
 	/// This includes refunding surplus weight, trapping extra holding funds, and returning any
 	/// errors during execution.
@@ -468,6 +403,154 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		Ok(())
 	}
 
+	fn take_fee(&mut self, fee: MultiAssets, reason: FeeReason) -> XcmResult {
+		if Config::FeeManager::is_waived(self.origin_ref(), reason) {
+			return Ok(())
+		}
+		log::trace!(
+			target: "xcm::fees",
+			"taking fee: {:?} from origin_ref: {:?} in fees_mode: {:?} for a reason: {:?}",
+			fee,
+			self.origin_ref(),
+			self.fees_mode,
+			reason,
+		);
+		let paid = if self.fees_mode.jit_withdraw {
+			let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?;
+			for asset in fee.inner() {
+				Config::AssetTransactor::withdraw_asset(&asset, origin, Some(&self.context))?;
+			}
+			fee
+		} else {
+			self.holding.try_take(fee.into()).map_err(|_| XcmError::NotHoldingFees)?.into()
+		};
+		Config::FeeManager::handle_fee(paid, Some(&self.context), reason);
+		Ok(())
+	}
+
+	/// Calculates what `local_querier` would be from the perspective of `destination`.
+	fn to_querier(
+		local_querier: Option<MultiLocation>,
+		destination: &MultiLocation,
+	) -> Result<Option<MultiLocation>, XcmError> {
+		Ok(match local_querier {
+			None => None,
+			Some(q) => Some(
+				q.reanchored(&destination, Config::UniversalLocation::get())
+					.map_err(|_| XcmError::ReanchorFailed)?,
+			),
+		})
+	}
+
+	/// Send a bare `QueryResponse` message containing `response` informed by the given `info`.
+	///
+	/// The `local_querier` argument is the querier (if any) specified from the *local* perspective.
+	fn respond(
+		&mut self,
+		local_querier: Option<MultiLocation>,
+		response: Response,
+		info: QueryResponseInfo,
+		fee_reason: FeeReason,
+	) -> Result<XcmHash, XcmError> {
+		let querier = Self::to_querier(local_querier, &info.destination)?;
+		let QueryResponseInfo { destination, query_id, max_weight } = info;
+		let instruction = QueryResponse { query_id, response, max_weight, querier };
+		let message = Xcm(vec![instruction]);
+		self.send(destination, message, fee_reason)
+	}
+
+	fn try_reanchor(
+		asset: MultiAsset,
+		destination: &MultiLocation,
+	) -> Result<(MultiAsset, InteriorMultiLocation), XcmError> {
+		let reanchor_context = Config::UniversalLocation::get();
+		let asset = asset
+			.reanchored(&destination, reanchor_context)
+			.map_err(|()| XcmError::ReanchorFailed)?;
+		Ok((asset, reanchor_context))
+	}
+
+	fn try_reanchor_multilocation(
+		location: MultiLocation,
+		destination: &MultiLocation,
+	) -> Result<(MultiLocation, InteriorMultiLocation), XcmError> {
+		let reanchor_context = Config::UniversalLocation::get();
+		let location = location
+			.reanchored(&destination, reanchor_context)
+			.map_err(|_| XcmError::ReanchorFailed)?;
+		Ok((location, reanchor_context))
+	}
+
+	/// NOTE: Any assets which were unable to be reanchored are introduced into `failed_bin`.
+	fn reanchored(
+		mut assets: Assets,
+		dest: &MultiLocation,
+		maybe_failed_bin: Option<&mut Assets>,
+	) -> MultiAssets {
+		let reanchor_context = Config::UniversalLocation::get();
+		assets.reanchor(dest, reanchor_context, maybe_failed_bin);
+		assets.into_assets_iter().collect::<Vec<_>>().into()
+	}
+
+	#[cfg(feature = "runtime-benchmarks")]
+	pub fn bench_process(&mut self, xcm: Xcm<Config::RuntimeCall>) -> Result<(), ExecutorError> {
+		self.process(xcm)
+	}
+
+	fn process(&mut self, xcm: Xcm<Config::RuntimeCall>) -> Result<(), ExecutorError> {
+		log::trace!(
+			target: "xcm::process",
+			"origin: {:?}, total_surplus/refunded: {:?}/{:?}, error_handler_weight: {:?}",
+			self.origin_ref(),
+			self.total_surplus,
+			self.total_refunded,
+			self.error_handler_weight,
+		);
+		let mut result = Ok(());
+		for (i, instr) in xcm.0.into_iter().enumerate() {
+			match &mut result {
+				r @ Ok(()) => {
+					// Initialize the recursion count only the first time we hit this code in our
+					// potential recursive execution.
+					let inst_res = recursion_count::using_once(&mut 1, || {
+						recursion_count::with(|count| {
+							if *count > RECURSION_LIMIT {
+								return Err(XcmError::ExceedsStackLimit)
+							}
+							*count = count.saturating_add(1);
+							Ok(())
+						})
+						// This should always return `Some`, but let's play it safe.
+						.unwrap_or(Ok(()))?;
+
+						// Ensure that we always decrement the counter whenever we finish processing
+						// the instruction.
+						defer! {
+							recursion_count::with(|count| {
+								*count = count.saturating_sub(1);
+							});
+						}
+
+						self.process_instruction(instr)
+					});
+					if let Err(e) = inst_res {
+						log::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e);
+						*r = Err(ExecutorError {
+							index: i as u32,
+							xcm_error: e,
+							weight: Weight::zero(),
+						});
+					}
+				},
+				Err(ref mut error) =>
+					if let Ok(x) = Config::Weigher::instr_weight(&instr) {
+						error.weight.saturating_accrue(x)
+					},
+			}
+		}
+		result
+	}
+
 	/// Process a single XCM instruction, mutating the state of the XCM virtual machine.
 	fn process_instruction(
 		&mut self,
@@ -551,22 +634,81 @@ 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.origin_ref().ok_or(XcmError::BadOrigin)?;
+				let origin = *self.origin_ref().ok_or_else(|| {
+					log::trace!(
+						target: "xcm::process_instruction::transact",
+						"No origin provided",
+					);
+
+					XcmError::BadOrigin
+				})?;
 
 				// TODO: #2841 #TRANSACTFILTER allow the trait to issue filters for the relay-chain
-				let message_call = call.take_decoded().map_err(|_| XcmError::FailedToDecode)?;
-				ensure!(Config::SafeCallFilter::contains(&message_call), XcmError::NoPermission);
+				let message_call = call.take_decoded().map_err(|_| {
+					log::trace!(
+						target: "xcm::process_instruction::transact",
+						"Failed to decode call",
+					);
+
+					XcmError::FailedToDecode
+				})?;
+
+				log::trace!(
+					target: "xcm::process_instruction::transact",
+					"Processing call: {message_call:?}",
+				);
+
+				if !Config::SafeCallFilter::contains(&message_call) {
+					log::trace!(
+						target: "xcm::process_instruction::transact",
+						"Call filtered by `SafeCallFilter`",
+					);
+
+					return Err(XcmError::NoPermission)
+				}
+
 				let dispatch_origin = Config::OriginConverter::convert_origin(origin, origin_kind)
-					.map_err(|_| XcmError::BadOrigin)?;
+					.map_err(|_| {
+						log::trace!(
+							target: "xcm::process_instruction::transact",
+							"Failed to convert origin {origin:?} and origin kind {origin_kind:?} to a local origin."
+						);
+
+						XcmError::BadOrigin
+					})?;
+
+				log::trace!(
+					target: "xcm::process_instruction::transact",
+					"Dispatching with origin: {dispatch_origin:?}",
+				);
+
 				let weight = message_call.get_dispatch_info().weight;
-				ensure!(weight.all_lte(require_weight_at_most), XcmError::MaxWeightInvalid);
+
+				if !weight.all_lte(require_weight_at_most) {
+					log::trace!(
+						target: "xcm::process_instruction::transact",
+						"Max {weight} bigger than require at most {require_weight_at_most}",
+					);
+
+					return Err(XcmError::MaxWeightInvalid)
+				}
+
 				let maybe_actual_weight =
 					match Config::CallDispatcher::dispatch(message_call, dispatch_origin) {
 						Ok(post_info) => {
+							log::trace!(
+								target: "xcm::process_instruction::transact",
+								"Dispatch successful: {post_info:?}"
+							);
 							self.transact_status = MaybeErrorCode::Success;
 							post_info.actual_weight
 						},
 						Err(error_and_info) => {
+							log::trace!(
+								target: "xcm::process_instruction::transact",
+								"Dispatch failed {error_and_info:?}"
+							);
+
 							self.transact_status = error_and_info.error.encode().into();
 							error_and_info.post_info.actual_weight
 						},
@@ -946,93 +1088,4 @@ impl<Config: config::Config> XcmExecutor<Config> {
 			HrmpChannelClosing { .. } => Err(XcmError::Unimplemented),
 		}
 	}
-
-	fn take_fee(&mut self, fee: MultiAssets, reason: FeeReason) -> XcmResult {
-		if Config::FeeManager::is_waived(self.origin_ref(), reason) {
-			return Ok(())
-		}
-		log::trace!(
-			target: "xcm::fees",
-			"taking fee: {:?} from origin_ref: {:?} in fees_mode: {:?} for a reason: {:?}",
-			fee,
-			self.origin_ref(),
-			self.fees_mode,
-			reason,
-		);
-		let paid = if self.fees_mode.jit_withdraw {
-			let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?;
-			for asset in fee.inner() {
-				Config::AssetTransactor::withdraw_asset(&asset, origin, Some(&self.context))?;
-			}
-			fee
-		} else {
-			self.holding.try_take(fee.into()).map_err(|_| XcmError::NotHoldingFees)?.into()
-		};
-		Config::FeeManager::handle_fee(paid, Some(&self.context), reason);
-		Ok(())
-	}
-
-	/// Calculates what `local_querier` would be from the perspective of `destination`.
-	fn to_querier(
-		local_querier: Option<MultiLocation>,
-		destination: &MultiLocation,
-	) -> Result<Option<MultiLocation>, XcmError> {
-		Ok(match local_querier {
-			None => None,
-			Some(q) => Some(
-				q.reanchored(&destination, Config::UniversalLocation::get())
-					.map_err(|_| XcmError::ReanchorFailed)?,
-			),
-		})
-	}
-
-	/// Send a bare `QueryResponse` message containing `response` informed by the given `info`.
-	///
-	/// The `local_querier` argument is the querier (if any) specified from the *local* perspective.
-	fn respond(
-		&mut self,
-		local_querier: Option<MultiLocation>,
-		response: Response,
-		info: QueryResponseInfo,
-		fee_reason: FeeReason,
-	) -> Result<XcmHash, XcmError> {
-		let querier = Self::to_querier(local_querier, &info.destination)?;
-		let QueryResponseInfo { destination, query_id, max_weight } = info;
-		let instruction = QueryResponse { query_id, response, max_weight, querier };
-		let message = Xcm(vec![instruction]);
-		self.send(destination, message, fee_reason)
-	}
-
-	fn try_reanchor(
-		asset: MultiAsset,
-		destination: &MultiLocation,
-	) -> Result<(MultiAsset, InteriorMultiLocation), XcmError> {
-		let reanchor_context = Config::UniversalLocation::get();
-		let asset = asset
-			.reanchored(&destination, reanchor_context)
-			.map_err(|()| XcmError::ReanchorFailed)?;
-		Ok((asset, reanchor_context))
-	}
-
-	fn try_reanchor_multilocation(
-		location: MultiLocation,
-		destination: &MultiLocation,
-	) -> Result<(MultiLocation, InteriorMultiLocation), XcmError> {
-		let reanchor_context = Config::UniversalLocation::get();
-		let location = location
-			.reanchored(&destination, reanchor_context)
-			.map_err(|_| XcmError::ReanchorFailed)?;
-		Ok((location, reanchor_context))
-	}
-
-	/// NOTE: Any assets which were unable to be reanchored are introduced into `failed_bin`.
-	fn reanchored(
-		mut assets: Assets,
-		dest: &MultiLocation,
-		maybe_failed_bin: Option<&mut Assets>,
-	) -> MultiAssets {
-		let reanchor_context = Config::UniversalLocation::get();
-		assets.reanchor(dest, reanchor_context, maybe_failed_bin);
-		assets.into_assets_iter().collect::<Vec<_>>().into()
-	}
 }

prdoc/pr_2799.prdoc

@@ -0,0 +1,10 @@
+title: Improve XCM debuggability
+
+doc:
+  - audience: Runtime User
+    description: |
+      Adds more logging to XCM execution to improve its debuggability.
+
+crates:
+  - name: "staging-xcm-builder"
+  - name: "staging-xcm-executor"

substrate/primitives/runtime/src/traits.rs

@@ -1438,7 +1438,7 @@ pub trait Dispatchable {
 	/// Every function call from your runtime has an origin, which specifies where the extrinsic was
 	/// generated from. In the case of a signed extrinsic (transaction), the origin contains an
 	/// identifier for the caller. The origin can be empty in the case of an inherent extrinsic.
-	type RuntimeOrigin;
+	type RuntimeOrigin: Debug;
 	/// ...
 	type Config;
 	/// An opaque set of information attached to the transaction. This could be constructed anywhere