Add XCM Tracing (#3353)

* add missing bridges logging target

* trace send_xcm

* trace execute_xcm

* trace calls in xcm-executor

* trace tuple implementations of xcm traits

* update cargo.lock

* remove bridge log target

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* log argument formatting

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

polkadot/Cargo.lock

@@ -5248,6 +5248,7 @@ version = "0.1.0"
 dependencies = [
  "frame-support",
  "frame-system",
+ "log",
  "parity-scale-codec",
  "serde",
  "sp-runtime",
@@ -11846,6 +11847,7 @@ version = "0.9.8"
 dependencies = [
  "derivative",
  "impl-trait-for-tuples",
+ "log",
  "parity-scale-codec",
 ]
 

polkadot/xcm/Cargo.toml

@@ -9,6 +9,7 @@ edition = "2018"
 impl-trait-for-tuples = "0.2.0"
 parity-scale-codec = { version = "2.0.0", default-features = false, features = [ "derive" ] }
 derivative = {version = "2.2.0", default-features = false, features = [ "use_core" ] }
+log = { version = "0.4.14", default-features = false }
 
 [features]
 default = ["std"]

polkadot/xcm/pallet-xcm/Cargo.toml

@@ -7,6 +7,7 @@ version = "0.1.0"
 [dependencies]
 codec = { package = "parity-scale-codec", version = "2.0.0", default-features = false, features = ["derive"] }
 serde = { version = "1.0.101", optional = true, features = ["derive"] }
+log = { version = "0.4.14", default-features = false }
 
 sp-std = { git = "https://github.com/paritytech/substrate", default-features = false, branch = "master" }
 sp-runtime = { git = "https://github.com/paritytech/substrate", default-features = false, branch = "master" }

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

@@ -254,6 +254,7 @@ pub mod pallet {
 				MultiLocation::Null => message,
 				who => Xcm::<()>::RelayedFrom { who, message: Box::new(message) },
 			};
+			log::trace!(target: "xcm::send_xcm", "dest: {:?}, message: {:?}", &dest, &message);
 			T::XcmRouter::send_xcm(dest, message)
 		}
 

polkadot/xcm/src/v0/traits.rs

@@ -134,6 +134,13 @@ pub trait ExecuteXcm<Call> {
 	/// a basic hard-limit and the implementation may place further restrictions or requirements on weight and
 	/// other aspects.
 	fn execute_xcm(origin: MultiLocation, message: Xcm<Call>, weight_limit: Weight) -> Outcome {
+		log::debug!(
+			target: "xcm::execute_xcm",
+			"origin: {:?}, message: {:?}, weight_limit: {:?}",
+			origin,
+			message,
+			weight_limit,
+		);
 		Self::execute_xcm_in_credit(origin, message, weight_limit, 0)
 	}
 

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

@@ -47,6 +47,14 @@ impl<Config: config::Config> ExecuteXcm<Config::Call> for XcmExecutor<Config> {
 		weight_limit: Weight,
 		mut weight_credit: Weight,
 	) -> Outcome {
+		log::trace!(
+			target: "xcm::execute_xcm_in_credit",
+			"origin: {:?}, message: {:?}, weight_limit: {:?}, weight_credit: {:?}",
+			origin,
+			message,
+			weight_limit,
+			weight_credit,
+		);
 		// TODO: #2841 #HARDENXCM We should identify recursive bombs here and bail.
 		let mut message = Xcm::<Config::Call>::from(message);
 		let shallow_weight = match Config::Weigher::shallow(&mut message) {
@@ -67,6 +75,7 @@ impl<Config: config::Config> ExecuteXcm<Config::Call> for XcmExecutor<Config> {
 		let mut trader = Config::Trader::new();
 		let result = Self::do_execute_xcm(origin, true, message, &mut weight_credit, Some(shallow_weight), &mut trader);
 		drop(trader);
+		log::trace!(target: "xcm::execute_xcm", "result: {:?}", &result);
 		match result {
 			Ok(surplus) => Outcome::Complete(maximum_weight.saturating_sub(surplus)),
 			// TODO: #2841 #REALWEIGHT We can do better than returning `maximum_weight` here, and we should otherwise
@@ -94,6 +103,15 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		maybe_shallow_weight: Option<Weight>,
 		trader: &mut Config::Trader,
 	) -> Result<Weight, XcmError> {
+		log::trace!(
+			target: "xcm::do_execute_xcm",
+			"origin: {:?}, top_level: {:?}, message: {:?}, weight_credit: {:?}, maybe_shallow_weight: {:?}",
+			origin, 
+			top_level, 
+			message, 
+			weight_credit, 
+			maybe_shallow_weight,
+		);
 		// This is the weight of everything that cannot be paid for. This basically means all computation
 		// except any XCM which is behind an Order::BuyExecution.
 		let shallow_weight = maybe_shallow_weight
@@ -165,7 +183,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
 				}
 				Some((Assets::from(assets), effects))
 			}
-			(origin, Xcm::Transact { origin_type, require_weight_at_most,  mut call }) => {
+			(origin, Xcm::Transact { origin_type, require_weight_at_most, mut call }) => {
 				// We assume that the Relay-chain is allowed to use transact on this parachain.
 
 				// TODO: #2841 #TRANSACTFILTER allow the trait to issue filters for the relay-chain
@@ -225,6 +243,13 @@ impl<Config: config::Config> XcmExecutor<Config> {
 		effect: Order<Config::Call>,
 		trader: &mut Config::Trader,
 	) -> Result<Weight, XcmError> {
+		log::trace!(
+			target: "xcm::execute_effects",
+			"origin: {:?}, holding: {:?}, effect: {:?}",
+			origin,
+			holding,
+			effect,
+		);
 		let mut total_surplus = 0;
 		match effect {
 			Order::DepositAsset { assets, dest } => {

polkadot/xcm/xcm-executor/src/traits/conversion.rs

@@ -173,6 +173,12 @@ impl<O> ConvertOrigin<O> for Tuple {
 				r => return r
 			};
 		)* );
+		log::trace!(
+			target: "xcm::convert_origin",
+			"could not convert: origin: {:?}, kind: {:?}",
+			origin,
+			kind,
+		);
 		Err(origin)
 	}
 }

polkadot/xcm/xcm-executor/src/traits/filter_asset_location.rs

@@ -30,6 +30,12 @@ impl FilterAssetLocation for Tuple {
 		for_tuples!( #(
 			if Tuple::filter_asset_location(what, origin) { return true }
 		)* );
+		log::trace!(
+			target: "xcm::filter_asset_location",
+			"got filtered: what: {:?}, origin: {:?}",
+			what,
+			origin,
+		);
 		false
 	}
 }

polkadot/xcm/xcm-executor/src/traits/matches_fungible.rs

@@ -26,6 +26,7 @@ impl<Balance> MatchesFungible<Balance> for Tuple {
 		for_tuples!( #(
 			match Tuple::matches_fungible(a) { o @ Some(_) => return o, _ => () }
 		)* );
+		log::trace!(target: "xcm::matches_fungible", "did not match fungible asset: {:?}", &a);
 		None
 	}
 }

polkadot/xcm/xcm-executor/src/traits/matches_fungibles.rs

@@ -54,6 +54,7 @@ impl<
 		for_tuples!( #(
 			match Tuple::matches_fungibles(a) { o @ Ok(_) => return o, _ => () }
 		)* );
+		log::trace!(target: "xcm::matches_fungibles", "did not match fungibles asset: {:?}", &a);
 		Err(Error::AssetNotFound)
 	}
 }

polkadot/xcm/xcm-executor/src/traits/should_execute.rs

@@ -58,6 +58,15 @@ impl ShouldExecute for Tuple {
 				_ => (),
 			}
 		)* );
+		log::trace!(
+			target: "xcm::should_execute",
+			"did not pass barrier: origin: {:?}, top_level: {:?}, message: {:?}, shallow_weight: {:?}, weight_credit: {:?}",
+			origin,
+			top_level,
+			message,
+			shallow_weight,
+			weight_credit,
+		);
 		Err(())
 	}
 }

polkadot/xcm/xcm-executor/src/traits/transact_asset.rs

@@ -107,34 +107,64 @@ impl TransactAsset for Tuple {
 				r => return r,
 			}
 		)* );
+		log::trace!(
+			target: "xcm::TransactAsset::can_check_in",
+			"asset not found: what: {:?}, origin: {:?}",
+			what,
+			origin,
+		);
 		Err(XcmError::AssetNotFound)
 	}
+
 	fn check_in(origin: &MultiLocation, what: &MultiAsset) {
 		for_tuples!( #(
 			Tuple::check_in(origin, what);
 		)* );
 	}
+
 	fn check_out(dest: &MultiLocation, what: &MultiAsset) {
 		for_tuples!( #(
 			Tuple::check_out(dest, what);
 		)* );
 	}
+
 	fn deposit_asset(what: &MultiAsset, who: &MultiLocation) -> XcmResult {
 		for_tuples!( #(
 			match Tuple::deposit_asset(what, who) { o @ Ok(_) => return o, _ => () }
 		)* );
+		log::trace!(
+			target: "xcm::TransactAsset::deposit_asset",
+			"did not deposit asset: what: {:?}, who: {:?}",
+			what,
+			who,
+		);
 		Err(XcmError::Unimplemented)
 	}
+
 	fn withdraw_asset(what: &MultiAsset, who: &MultiLocation) -> Result<Assets, XcmError> {
 		for_tuples!( #(
 			match Tuple::withdraw_asset(what, who) { o @ Ok(_) => return o, _ => () }
 		)* );
+		log::trace!(
+			target: "xcm::TransactAsset::withdraw_asset",
+			"did not withdraw asset: what: {:?}, who: {:?}",
+			what, 
+			who,
+		);
 		Err(XcmError::Unimplemented)
 	}
+
 	fn transfer_asset(what: &MultiAsset, from: &MultiLocation, to: &MultiLocation) -> Result<Assets, XcmError> {
 		for_tuples!( #(
 			match Tuple::transfer_asset(what, from, to) { o @ Ok(_) => return o, _ => () }
 		)* );
+		log::trace!(
+			target: "xcm::TransactAsset::transfer_asset",
+			"did not transfer asset: what: {:?}, from: {:?}, to: {:?}",
+			what,
+			from,
+			to,
+		);
 		Err(XcmError::Unimplemented)
 	}
 }