xcm: Improve debuggability (#2799)

Adds more logging to the XCM execution for better debugging.

Author: bkchr

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"

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)
 	}
 }
 

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

xcm-builder/src/tests/mock.rs

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