Add more XCM tracing (#4211)

* add more logging to currency adapter

* add more logging to barriers

* reformat currency adapter trace logs

* add tracing logs for filter asset location

* add tracing logs to fungibles adapter

* add tracing to origin conversion

* add tracing logs for xcm weight trading

* fix compile errors

* add more tracing logs to xcm executor

* formatting and compile fixes

* add some tracing logs to pallet-xcm

* adjust log target in executor to debug

* fix closure args

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

@@ -1192,6 +1192,11 @@ pub mod pallet {
 		/// Note that a particular destination to whom we would like to send a message is unknown
 		/// and queue it for version discovery.
 		fn note_unknown_version(dest: &MultiLocation) {
+			log::trace!(
+				target: "xcm::pallet_xcm::note_unknown_version",
+				"XCM version is unknown for destination: {:?}",
+				dest,
+			);
 			let versioned_dest = VersionedMultiLocation::from(dest.clone());
 			VersionDiscoveryQueue::<T>::mutate(|q| {
 				if let Some(index) = q.iter().position(|i| &i.0 == &versioned_dest) {
@@ -1214,7 +1219,14 @@ pub mod pallet {
 					Self::note_unknown_version(dest);
 					SafeXcmVersion::<T>::get()
 				})
-				.ok_or(())
+				.ok_or_else(|| {
+					log::trace!(
+						target: "xcm::pallet_xcm::wrap_version",
+						"Could not determine a version to wrap XCM for destination: {:?}",
+						dest,
+					);
+					()
+				})
 				.and_then(|v| xcm.into().into_version(v.min(XCM_VERSION)))
 		}
 	}

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

@@ -35,6 +35,11 @@ impl ShouldExecute for TakeWeightCredit {
 		max_weight: Weight,
 		weight_credit: &mut Weight,
 	) -> Result<(), ()> {
+		log::trace!(
+			target: "xcm::barriers",
+			"TakeWeightCredit origin: {:?}, message: {:?}, max_weight: {:?}, weight_credit: {:?}",
+			_origin, _message, max_weight, weight_credit,
+		);
 		*weight_credit = weight_credit.checked_sub(max_weight).ok_or(())?;
 		Ok(())
 	}
@@ -53,6 +58,11 @@ impl<T: Contains<MultiLocation>> ShouldExecute for AllowTopLevelPaidExecutionFro
 		max_weight: Weight,
 		_weight_credit: &mut Weight,
 	) -> Result<(), ()> {
+		log::trace!(
+			target: "xcm::barriers",
+			"AllowTopLevelPaidExecutionFrom origin: {:?}, message: {:?}, max_weight: {:?}, weight_credit: {:?}",
+			origin, message, max_weight, _weight_credit,
+		);
 		ensure!(T::contains(origin), ());
 		let mut iter = message.0.iter_mut();
 		let i = iter.next().ok_or(())?;
@@ -91,6 +101,11 @@ impl<T: Contains<MultiLocation>> ShouldExecute for AllowUnpaidExecutionFrom<T> {
 		_max_weight: Weight,
 		_weight_credit: &mut Weight,
 	) -> Result<(), ()> {
+		log::trace!(
+			target: "xcm::barriers",
+			"AllowUnpaidExecutionFrom origin: {:?}, message: {:?}, max_weight: {:?}, weight_credit: {:?}",
+			origin, _message, _max_weight, _weight_credit,
+		);
 		ensure!(T::contains(origin), ());
 		Ok(())
 	}
@@ -117,6 +132,11 @@ impl<ResponseHandler: OnResponse> ShouldExecute for AllowKnownQueryResponses<Res
 		_max_weight: Weight,
 		_weight_credit: &mut Weight,
 	) -> Result<(), ()> {
+		log::trace!(
+			target: "xcm::barriers",
+			"AllowKnownQueryResponses origin: {:?}, message: {:?}, max_weight: {:?}, weight_credit: {:?}",
+			origin, message, _max_weight, _weight_credit,
+		);
 		match message.0.first() {
 			Some(QueryResponse { query_id, .. })
 				if ResponseHandler::expecting_response(origin, *query_id) =>
@@ -136,6 +156,11 @@ impl<T: Contains<MultiLocation>> ShouldExecute for AllowSubscriptionsFrom<T> {
 		_max_weight: Weight,
 		_weight_credit: &mut Weight,
 	) -> Result<(), ()> {
+		log::trace!(
+			target: "xcm::barriers",
+			"AllowSubscriptionsFrom origin: {:?}, message: {:?}, max_weight: {:?}, weight_credit: {:?}",
+			origin, message, _max_weight, _weight_credit,
+		);
 		ensure!(T::contains(origin), ());
 		match (message.0.len(), message.0.first()) {
 			(1, Some(SubscribeVersion { .. })) | (1, Some(UnsubscribeVersion)) => Ok(()),

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

@@ -97,6 +97,7 @@ impl<
 	for CurrencyAdapter<Currency, Matcher, AccountIdConverter, AccountId, CheckedAccount>
 {
 	fn can_check_in(_origin: &MultiLocation, what: &MultiAsset) -> Result {
+		log::trace!(target: "xcm::currency_adapter", "can_check_in origin: {:?}, what: {:?}", _origin, what);
 		// Check we handle this asset.
 		let amount: Currency::Balance =
 			Matcher::matches_fungible(what).ok_or(Error::AssetNotFound)?;
@@ -116,6 +117,7 @@ impl<
 	}
 
 	fn check_in(_origin: &MultiLocation, what: &MultiAsset) {
+		log::trace!(target: "xcm::currency_adapter", "check_in origin: {:?}, what: {:?}", _origin, what);
 		if let Some(amount) = Matcher::matches_fungible(what) {
 			if let Some(checked_account) = CheckedAccount::get() {
 				let ok = Currency::withdraw(
@@ -134,6 +136,7 @@ impl<
 	}
 
 	fn check_out(_dest: &MultiLocation, what: &MultiAsset) {
+		log::trace!(target: "xcm::currency_adapter", "check_out dest: {:?}, what: {:?}", _dest, what);
 		if let Some(amount) = Matcher::matches_fungible(what) {
 			if let Some(checked_account) = CheckedAccount::get() {
 				Currency::deposit_creating(&checked_account, amount);
@@ -142,7 +145,7 @@ impl<
 	}
 
 	fn deposit_asset(what: &MultiAsset, who: &MultiLocation) -> Result {
-		log::trace!("xcm::currency_adapter deposit_asset {:?} {:?}", what, who);
+		log::trace!(target: "xcm::currency_adapter", "deposit_asset what: {:?}, who: {:?}", what, who);
 		// Check we handle this asset.
 		let amount: u128 =
 			Matcher::matches_fungible(&what).ok_or(Error::AssetNotFound)?.saturated_into();
@@ -155,6 +158,7 @@ impl<
 	}
 
 	fn withdraw_asset(what: &MultiAsset, who: &MultiLocation) -> result::Result<Assets, XcmError> {
+		log::trace!(target: "xcm::currency_adapter", "withdraw_asset what: {:?}, who: {:?}", what, who);
 		// Check we handle this asset.
 		let amount: u128 =
 			Matcher::matches_fungible(what).ok_or(Error::AssetNotFound)?.saturated_into();

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

@@ -25,6 +25,7 @@ use xcm_executor::traits::FilterAssetLocation;
 pub struct NativeAsset;
 impl FilterAssetLocation for NativeAsset {
 	fn filter_asset_location(asset: &MultiAsset, origin: &MultiLocation) -> bool {
+		log::trace!(target: "xcm::filter_asset_location", "NativeAsset asset: {:?}, origin: {:?}", asset, origin);
 		matches!(asset.id, Concrete(ref id) if id == origin)
 	}
 }
@@ -33,6 +34,7 @@ impl FilterAssetLocation for NativeAsset {
 pub struct Case<T>(PhantomData<T>);
 impl<T: Get<(MultiAssetFilter, MultiLocation)>> FilterAssetLocation for Case<T> {
 	fn filter_asset_location(asset: &MultiAsset, origin: &MultiLocation) -> bool {
+		log::trace!(target: "xcm::filter_asset_location", "Case asset: {:?}, origin: {:?}", asset, origin);
 		let (a, o) = T::get();
 		a.contains(asset) && &o == origin
 	}

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

@@ -123,6 +123,11 @@ impl<
 		from: &MultiLocation,
 		to: &MultiLocation,
 	) -> result::Result<xcm_executor::Assets, XcmError> {
+		log::trace!(
+			target: "xcm::fungibles_adapter",
+			"transfer_asset what: {:?}, from: {:?}, to: {:?}",
+			what, from, to
+		);
 		// Check we handle this asset.
 		let (asset_id, amount) = Matcher::matches_fungibles(what)?;
 		let source = AccountIdConverter::convert_ref(from)
@@ -161,6 +166,11 @@ impl<
 	>
 {
 	fn can_check_in(_origin: &MultiLocation, what: &MultiAsset) -> Result {
+		log::trace!(
+			target: "xcm::fungibles_adapter",
+			"can_check_in origin: {:?}, what: {:?}",
+			_origin, what
+		);
 		// Check we handle this asset.
 		let (asset_id, amount) = Matcher::matches_fungibles(what)?;
 		if CheckAsset::contains(&asset_id) {
@@ -174,6 +184,11 @@ impl<
 	}
 
 	fn check_in(_origin: &MultiLocation, what: &MultiAsset) {
+		log::trace!(
+			target: "xcm::fungibles_adapter",
+			"check_in origin: {:?}, what: {:?}",
+			_origin, what
+		);
 		if let Ok((asset_id, amount)) = Matcher::matches_fungibles(what) {
 			if CheckAsset::contains(&asset_id) {
 				let checking_account = CheckingAccount::get();
@@ -187,6 +202,11 @@ impl<
 	}
 
 	fn check_out(_dest: &MultiLocation, what: &MultiAsset) {
+		log::trace!(
+			target: "xcm::fungibles_adapter",
+			"check_out dest: {:?}, what: {:?}",
+			_dest, what
+		);
 		if let Ok((asset_id, amount)) = Matcher::matches_fungibles(what) {
 			if CheckAsset::contains(&asset_id) {
 				let checking_account = CheckingAccount::get();
@@ -197,6 +217,11 @@ impl<
 	}
 
 	fn deposit_asset(what: &MultiAsset, who: &MultiLocation) -> Result {
+		log::trace!(
+			target: "xcm::fungibles_adapter",
+			"deposit_asset what: {:?}, who: {:?}",
+			what, who,
+		);
 		// Check we handle this asset.
 		let (asset_id, amount) = Matcher::matches_fungibles(what)?;
 		let who = AccountIdConverter::convert_ref(who)
@@ -209,6 +234,11 @@ impl<
 		what: &MultiAsset,
 		who: &MultiLocation,
 	) -> result::Result<xcm_executor::Assets, XcmError> {
+		log::trace!(
+			target: "xcm::fungibles_adapter",
+			"withdraw_asset what: {:?}, who: {:?}",
+			what, who,
+		);
 		// Check we handle this asset.
 		let (asset_id, amount) = Matcher::matches_fungibles(what)?;
 		let who = AccountIdConverter::convert_ref(who)

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

@@ -37,6 +37,11 @@ where
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
 		let origin = origin.into();
+		log::trace!(
+			target: "xcm::origin_conversion",
+			"SovereignSignedViaLocation origin: {:?}, kind: {:?}",
+			origin, kind,
+		);
 		if let OriginKind::SovereignAccount = kind {
 			let location = LocationConverter::convert(origin)?;
 			Ok(Origin::signed(location).into())
@@ -53,6 +58,7 @@ impl<Origin: OriginTrait> ConvertOrigin<Origin> for ParentAsSuperuser<Origin> {
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
 		let origin = origin.into();
+		log::trace!(target: "xcm::origin_conversion", "ParentAsSuperuser origin: {:?}, kind: {:?}", origin, kind);
 		if kind == OriginKind::Superuser && origin.contains_parents_only(1) {
 			Ok(Origin::root())
 		} else {
@@ -69,7 +75,9 @@ impl<ParaId: IsSystem + From<u32>, Origin: OriginTrait> ConvertOrigin<Origin>
 		origin: impl Into<MultiLocation>,
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
-		match (kind, origin.into()) {
+		let origin = origin.into();
+		log::trace!(target: "xcm::origin_conversion", "ChildSystemParachainAsSuperuser origin: {:?}, kind: {:?}", origin, kind);
+		match (kind, origin) {
 			(
 				OriginKind::Superuser,
 				MultiLocation { parents: 0, interior: X1(Junction::Parachain(id)) },
@@ -87,7 +95,13 @@ impl<ParaId: IsSystem + From<u32>, Origin: OriginTrait> ConvertOrigin<Origin>
 		origin: impl Into<MultiLocation>,
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
-		match (kind, origin.into()) {
+		let origin = origin.into();
+		log::trace!(
+			target: "xcm::origin_conversion",
+			"SiblingSystemParachainAsSuperuser origin: {:?}, kind: {:?}",
+			origin, kind,
+		);
+		match (kind, origin) {
 			(
 				OriginKind::Superuser,
 				MultiLocation { parents: 1, interior: X1(Junction::Parachain(id)) },
@@ -105,7 +119,9 @@ impl<ParachainOrigin: From<u32>, Origin: From<ParachainOrigin>> ConvertOrigin<Or
 		origin: impl Into<MultiLocation>,
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
-		match (kind, origin.into()) {
+		let origin = origin.into();
+		log::trace!(target: "xcm::origin_conversion", "ChildParachainAsNative origin: {:?}, kind: {:?}", origin, kind);
+		match (kind, origin) {
 			(
 				OriginKind::Native,
 				MultiLocation { parents: 0, interior: X1(Junction::Parachain(id)) },
@@ -125,7 +141,13 @@ impl<ParachainOrigin: From<u32>, Origin: From<ParachainOrigin>> ConvertOrigin<Or
 		origin: impl Into<MultiLocation>,
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
-		match (kind, origin.into()) {
+		let origin = origin.into();
+		log::trace!(
+			target: "xcm::origin_conversion",
+			"SiblingParachainAsNative origin: {:?}, kind: {:?}",
+			origin, kind,
+		);
+		match (kind, origin) {
 			(
 				OriginKind::Native,
 				MultiLocation { parents: 1, interior: X1(Junction::Parachain(id)) },
@@ -145,6 +167,7 @@ impl<RelayOrigin: Get<Origin>, Origin> ConvertOrigin<Origin>
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
 		let origin = origin.into();
+		log::trace!(target: "xcm::origin_conversion", "RelayChainAsNative origin: {:?}, kind: {:?}", origin, kind);
 		if kind == OriginKind::Native && origin.contains_parents_only(1) {
 			Ok(RelayOrigin::get())
 		} else {
@@ -163,7 +186,13 @@ where
 		origin: impl Into<MultiLocation>,
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
-		match (kind, origin.into()) {
+		let origin = origin.into();
+		log::trace!(
+			target: "xcm::origin_conversion",
+			"SignedAccountId32AsNative origin: {:?}, kind: {:?}",
+			origin, kind,
+		);
+		match (kind, origin) {
 			(
 				OriginKind::Native,
 				MultiLocation { parents: 0, interior: X1(Junction::AccountId32 { id, network }) },
@@ -184,7 +213,13 @@ where
 		origin: impl Into<MultiLocation>,
 		kind: OriginKind,
 	) -> Result<Origin, MultiLocation> {
-		match (kind, origin.into()) {
+		let origin = origin.into();
+		log::trace!(
+			target: "xcm::origin_conversion",
+			"SignedAccountKey20AsNative origin: {:?}, kind: {:?}",
+			origin, kind,
+		);
+		match (kind, origin) {
 			(
 				OriginKind::Native,
 				MultiLocation { parents: 0, interior: X1(Junction::AccountKey20 { key, network }) },

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

@@ -32,6 +32,7 @@ impl<T: Get<Weight>, C: Decode + GetDispatchInfo, M: Get<u32>> WeightBounds<C>
 	for FixedWeightBounds<T, C, M>
 {
 	fn weight(message: &mut Xcm<C>) -> Result<Weight, ()> {
+		log::trace!(target: "xcm::weight", "FixedWeightBounds message: {:?}", message);
 		let mut instructions_left = M::get();
 		Self::weight_with_limit(message, &mut instructions_left)
 	}
@@ -73,6 +74,7 @@ where
 	Instruction<C>: xcm::GetWeight<W>,
 {
 	fn weight(message: &mut Xcm<C>) -> Result<Weight, ()> {
+		log::trace!(target: "xcm::weight", "WeightInfoBounds message: {:?}", message);
 		let mut instructions_left = M::get();
 		Self::weight_with_limit(message, &mut instructions_left)
 	}
@@ -144,6 +146,11 @@ impl<T: Get<(MultiLocation, u128)>, R: TakeRevenue> WeightTrader
 	}
 
 	fn buy_weight(&mut self, weight: Weight, payment: Assets) -> Result<Assets, XcmError> {
+		log::trace!(
+			target: "xcm::weight",
+			"FixedRateOfConcreteFungible::buy_weight weight: {:?}, payment: {:?}",
+			weight, payment,
+		);
 		let (id, units_per_second) = T::get();
 		let amount = units_per_second * (weight as u128) / (WEIGHT_PER_SECOND as u128);
 		let unused =
@@ -154,6 +161,7 @@ impl<T: Get<(MultiLocation, u128)>, R: TakeRevenue> WeightTrader
 	}
 
 	fn refund_weight(&mut self, weight: Weight) -> Option<MultiAsset> {
+		log::trace!(target: "xcm::weight", "FixedRateOfConcreteFungible::refund_weight weight: {:?}", weight);
 		let (id, units_per_second) = T::get();
 		let weight = weight.min(self.0);
 		let amount = units_per_second * (weight as u128) / (WEIGHT_PER_SECOND as u128);
@@ -190,6 +198,11 @@ impl<T: Get<(AssetId, u128)>, R: TakeRevenue> WeightTrader for FixedRateOfFungib
 	}
 
 	fn buy_weight(&mut self, weight: Weight, payment: Assets) -> Result<Assets, XcmError> {
+		log::trace!(
+			target: "xcm::weight",
+			"FixedRateOfFungible::buy_weight weight: {:?}, payment: {:?}",
+			weight, payment,
+		);
 		let (id, units_per_second) = T::get();
 		let amount = units_per_second * (weight as u128) / (WEIGHT_PER_SECOND as u128);
 		if amount == 0 {
@@ -203,6 +216,7 @@ impl<T: Get<(AssetId, u128)>, R: TakeRevenue> WeightTrader for FixedRateOfFungib
 	}
 
 	fn refund_weight(&mut self, weight: Weight) -> Option<MultiAsset> {
+		log::trace!(target: "xcm::weight", "FixedRateOfFungible::refund_weight weight: {:?}", weight);
 		let (id, units_per_second) = T::get();
 		let weight = weight.min(self.0);
 		let amount = units_per_second * (weight as u128) / (WEIGHT_PER_SECOND as u128);
@@ -250,6 +264,7 @@ impl<
 	}
 
 	fn buy_weight(&mut self, weight: Weight, payment: Assets) -> Result<Assets, XcmError> {
+		log::trace!(target: "xcm::weight", "UsingComponents::buy_weight weight: {:?}, payment: {:?}", weight, payment);
 		let amount = WeightToFee::calc(&weight);
 		let u128_amount: u128 = amount.try_into().map_err(|_| XcmError::Overflow)?;
 		let required = (Concrete(AssetId::get()), u128_amount).into();
@@ -260,6 +275,7 @@ impl<
 	}
 
 	fn refund_weight(&mut self, weight: Weight) -> Option<MultiAsset> {
+		log::trace!(target: "xcm::weight", "UsingComponents::refund_weight weight: {:?}", weight);
 		let weight = weight.min(self.0);
 		let amount = WeightToFee::calc(&weight);
 		self.0 -= weight;

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

@@ -83,15 +83,44 @@ impl<Config: config::Config> ExecuteXcm<Config::Call> for XcmExecutor<Config> {
 		);
 		let xcm_weight = match Config::Weigher::weight(&mut message) {
 			Ok(x) => x,
-			Err(()) => return Outcome::Error(XcmError::WeightNotComputable),
+			Err(()) => {
+				log::debug!(
+					target: "xcm::execute_xcm_in_credit",
+					"Weight not computable! (origin: {:?}, message: {:?}, weight_limit: {:?}, weight_credit: {:?})",
+					origin,
+					message,
+					weight_limit,
+					weight_credit,
+				);
+				return Outcome::Error(XcmError::WeightNotComputable)
+			},
 		};
 		if xcm_weight > weight_limit {
+			log::debug!(
+				target: "xcm::execute_xcm_in_credit",
+				"Weight limit reached! weight > weight_limit: {:?} > {:?}. (origin: {:?}, message: {:?}, weight_limit: {:?}, weight_credit: {:?})",
+				xcm_weight,
+				weight_limit,
+				origin,
+				message,
+				weight_limit,
+				weight_credit,
+			);
 			return Outcome::Error(XcmError::WeightLimitReached(xcm_weight))
 		}
 
-		if let Err(_) =
+		if let Err(e) =
 			Config::Barrier::should_execute(&origin, &mut message, xcm_weight, &mut weight_credit)
 		{
+			log::debug!(
+				target: "xcm::execute_xcm_in_credit",
+				"Barrier blocked execution! Error: {:?}. (origin: {:?}, message: {:?}, weight_limit: {:?}, weight_credit: {:?})",
+				e,
+				origin,
+				message,
+				weight_limit,
+				weight_credit,
+			);
 			return Outcome::Error(XcmError::Barrier)
 		}
 
@@ -116,6 +145,7 @@ impl<Config: config::Config> ExecuteXcm<Config::Call> for XcmExecutor<Config> {
 		let mut weight_used = xcm_weight.saturating_sub(vm.total_surplus);
 
 		if !vm.holding.is_empty() {
+			log::trace!(target: "xcm::execute_xcm_in_credit", "Trapping assets in holding register: {:?} (original_origin: {:?})", vm.holding, vm.original_origin);
 			let trap_weight = Config::AssetTrap::drop_assets(&vm.original_origin, vm.holding);
 			weight_used.saturating_accrue(trap_weight);
 		};
@@ -124,7 +154,10 @@ impl<Config: config::Config> ExecuteXcm<Config::Call> for XcmExecutor<Config> {
 			None => Outcome::Complete(weight_used),
 			// TODO: #2841 #REALWEIGHT We should deduct the cost of any instructions following
 			// the error which didn't end up being executed.
-			Some((_, e)) => Outcome::Incomplete(weight_used, e),
+			Some((_i, e)) => {
+				log::debug!(target: "xcm::execute_xcm_in_credit", "Execution errored at {:?}: {:?} (original_origin: {:?})", _i, e, vm.original_origin);
+				Outcome::Incomplete(weight_used, e)
+			},
 		}
 	}
 }