xcm-builder: added logging for xcm filters/helpers/matchers/types (paritytech#2408) (paritytech#7003)

# Description

Added logs in pallet-xcm to help in debugging, fixes paritytech#2408, and in
continuation of paritytech#4982

# Checklist

- [x]
https://github.com/paritytech/polkadot-sdk/blob/master/polkadot/xcm/xcm-builder/src/
- [x]
https://github.com/paritytech/polkadot-sdk/tree/master/cumulus/parachains/runtimes/assets/common/src
- [x] runtime-defined XCM filters/converters (just [one
example](https://github.com/paritytech/polkadot-sdk/blob/183b55aae21e97ef39192e5a358287e2b6b7043c/cumulus/parachains/runtimes/bridge-hubs/bridge-hub-westend/src/xcm_config.rs#L284))

Polkadot Address: 1Gz5aLtEu2n4jsfA6XwtZnuaRymJrDDw4kEGdNHTdxrpzrc

---------

Co-authored-by: Ayevbeosa Iyamu <[email protected]>
Co-authored-by: Bastian Köcher <[email protected]>
Co-authored-by: Adrian Catangiu <[email protected]>
Co-authored-by: Raymond Cheung <[email protected]>
Co-authored-by: cmd[bot] <41898282+github-actions[bot]@users.noreply.github.com>

Author: 6 people

Cargo.lock

@@ -14,8 +14,8 @@ workspace = true
 [dependencies]
 codec = { features = ["derive"], workspace = true }
 impl-trait-for-tuples = { workspace = true }
-log = { workspace = true }
 scale-info = { features = ["derive"], workspace = true }
+tracing = { workspace = true }
 
 # Substrate
 frame-support = { workspace = true }
@@ -43,14 +43,14 @@ std = [
 	"codec/std",
 	"cumulus-primitives-core/std",
 	"frame-support/std",
-	"log/std",
 	"pallet-asset-conversion/std",
 	"pallet-assets/std",
 	"pallet-xcm/std",
 	"parachains-common/std",
 	"scale-info/std",
 	"sp-api/std",
 	"sp-runtime/std",
+	"tracing/std",
 	"xcm-builder/std",
 	"xcm-executor/std",
 	"xcm/std",

cumulus/parachains/runtimes/assets/common/Cargo.toml

@@ -13,7 +13,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-use core::marker::PhantomData;
+use core::{fmt::Debug, marker::PhantomData};
 use cumulus_primitives_core::ParaId;
 use sp_runtime::traits::Get;
 use xcm::latest::prelude::*;
@@ -22,8 +22,10 @@ use xcm::latest::prelude::*;
 pub struct AssetPairFactory<Target, SelfParaId, PalletId, L = Location>(
 	PhantomData<(Target, SelfParaId, PalletId, L)>,
 );
-impl<Target: Get<L>, SelfParaId: Get<ParaId>, PalletId: Get<u32>, L: TryFrom<Location>>
+impl<Target: Get<L>, SelfParaId: Get<ParaId>, PalletId: Get<u32>, L: TryFrom<Location> + Debug>
 	pallet_asset_conversion::BenchmarkHelper<L> for AssetPairFactory<Target, SelfParaId, PalletId, L>
+where
+	<L as TryFrom<Location>>::Error: Debug,
 {
 	fn create_pair(seed1: u32, seed2: u32) -> (L, L) {
 		let with_id = Location::new(
@@ -35,9 +37,31 @@ impl<Target: Get<L>, SelfParaId: Get<ParaId>, PalletId: Get<u32>, L: TryFrom<Loc
 			],
 		);
 		if seed1 % 2 == 0 {
-			(with_id.try_into().map_err(|_| "Something went wrong").unwrap(), Target::get())
+			(
+				with_id
+					.try_into()
+					.map_err(|error| {
+						tracing::error!(
+							target: "xcm",
+							?error,
+							"Failed to create asset pairs when seed1 is even",
+						);
+						"Something went wrong"
+					})
+					.unwrap(),
+				Target::get(),
+			)
 		} else {
-			(Target::get(), with_id.try_into().map_err(|_| "Something went wrong").unwrap())
+			(
+				Target::get(),
+				with_id
+					.try_into()
+					.map_err(|error| {
+						tracing::error!(target: "xcm", ?error, "Failed to create asset pairs");
+						"Something went wrong"
+					})
+					.unwrap(),
+			)
 		}
 	}
 }

cumulus/parachains/runtimes/assets/common/src/benchmarks.rs

@@ -13,6 +13,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+use core::fmt::Debug;
 use frame_support::traits::{
 	ContainsPair, EnsureOrigin, EnsureOriginWithArg, Everything, OriginTrait,
 };
@@ -29,8 +30,8 @@ impl<
 		IsForeign: ContainsPair<L, L>,
 		AccountOf: ConvertLocation<AccountId>,
 		AccountId: Clone,
-		RuntimeOrigin: From<XcmOrigin> + OriginTrait + Clone,
-		L: TryFrom<Location> + TryInto<Location> + Clone,
+		RuntimeOrigin: From<XcmOrigin> + OriginTrait + Clone + Debug,
+		L: TryFrom<Location> + TryInto<Location> + Clone + Debug,
 	> EnsureOriginWithArg<RuntimeOrigin, L> for ForeignCreators<IsForeign, AccountOf, AccountId, L>
 where
 	RuntimeOrigin::PalletsOrigin:
@@ -42,8 +43,10 @@ where
 		origin: RuntimeOrigin,
 		asset_location: &L,
 	) -> core::result::Result<Self::Success, RuntimeOrigin> {
+		tracing::trace!(target: "xcm::try_origin", ?origin, ?asset_location, "ForeignCreators");
 		let origin_location = EnsureXcm::<Everything, L>::try_origin(origin.clone())?;
 		if !IsForeign::contains(asset_location, &origin_location) {
+			tracing::trace!(target: "xcm::try_origin", ?asset_location, ?origin_location, "ForeignCreators: no match");
 			return Err(origin)
 		}
 		let latest_location: Location =

cumulus/parachains/runtimes/assets/common/src/foreign_creators.rs

@@ -117,7 +117,7 @@ impl<
 		for_tuples!( #(
 			match Tuple::contains(location) { o @ true => return o, _ => () }
 		)* );
-		log::trace!(target: "xcm::contains", "did not match location: {:?}", &location);
+		tracing::trace!(target: "xcm::contains", ?location, "MatchesLocation: no match");
 		false
 	}
 }

cumulus/parachains/runtimes/assets/common/src/fungible_conversion.rs

@@ -24,6 +24,7 @@ pub mod matching;
 pub mod runtime_api;
 
 extern crate alloc;
+extern crate core;
 
 use crate::matching::{LocalLocationPattern, ParentLocation};
 use alloc::vec::Vec;

cumulus/parachains/runtimes/assets/common/src/lib.rs

@@ -13,6 +13,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+use core::fmt::Debug;
 use cumulus_primitives_core::ParaId;
 use frame_support::{
 	pallet_prelude::Get,
@@ -33,8 +34,9 @@ impl<IsForeign: ContainsPair<Location, Location>> ContainsPair<Asset, Location>
 	for IsForeignConcreteAsset<IsForeign>
 {
 	fn contains(asset: &Asset, origin: &Location) -> bool {
-		log::trace!(target: "xcm::contains", "IsForeignConcreteAsset asset: {:?}, origin: {:?}", asset, origin);
-		matches!(asset.id, AssetId(ref id) if IsForeign::contains(id, origin))
+		let result = matches!(asset.id, AssetId(ref id) if IsForeign::contains(id, origin));
+		tracing::trace!(target: "xcm::contains", ?asset, ?origin, ?result, "IsForeignConcreteAsset");
+		result
 	}
 }
 
@@ -43,10 +45,11 @@ impl<IsForeign: ContainsPair<Location, Location>> ContainsPair<Asset, Location>
 pub struct FromSiblingParachain<SelfParaId, L = Location>(
 	core::marker::PhantomData<(SelfParaId, L)>,
 );
-impl<SelfParaId: Get<ParaId>, L: TryFrom<Location> + TryInto<Location> + Clone> ContainsPair<L, L>
-	for FromSiblingParachain<SelfParaId, L>
+impl<SelfParaId: Get<ParaId>, L: TryFrom<Location> + TryInto<Location> + Clone + Debug>
+	ContainsPair<L, L> for FromSiblingParachain<SelfParaId, L>
 {
 	fn contains(a: &L, b: &L) -> bool {
+		tracing::trace!(target: "xcm:contains", ?a, ?b, "FromSiblingParachain");
 		// We convert locations to latest
 		let a = match ((*a).clone().try_into(), (*b).clone().try_into()) {
 			(Ok(a), Ok(b)) if a.starts_with(&b) => a, // `a` needs to be from `b` at least
@@ -70,10 +73,11 @@ pub struct FromNetwork<UniversalLocation, ExpectedNetworkId, L = Location>(
 impl<
 		UniversalLocation: Get<InteriorLocation>,
 		ExpectedNetworkId: Get<NetworkId>,
-		L: TryFrom<Location> + TryInto<Location> + Clone,
+		L: TryFrom<Location> + TryInto<Location> + Clone + Debug,
 	> ContainsPair<L, L> for FromNetwork<UniversalLocation, ExpectedNetworkId, L>
 {
 	fn contains(a: &L, b: &L) -> bool {
+		tracing::trace!(target: "xcm:contains", ?a, ?b, "FromNetwork");
 		// We convert locations to latest
 		let a = match ((*a).clone().try_into(), (*b).clone().try_into()) {
 			(Ok(a), Ok(b)) if a.starts_with(&b) => a, // `a` needs to be from `b` at least
@@ -86,11 +90,7 @@ impl<
 		match ensure_is_remote(universal_source.clone(), a.clone()) {
 			Ok((network_id, _)) => network_id == ExpectedNetworkId::get(),
 			Err(e) => {
-				log::trace!(
-					target: "xcm::contains",
-					"FromNetwork origin: {:?} is not remote to the universal_source: {:?} {:?}",
-					a, universal_source, e
-				);
+				tracing::debug!(target: "xcm::contains", origin = ?a, ?universal_source, error = ?e, "FromNetwork origin is not remote to the universal_source");
 				false
 			},
 		}
@@ -118,15 +118,20 @@ impl<
 		let expected_origin = OriginLocation::get();
 		// ensure `origin` is expected `OriginLocation`
 		if !expected_origin.eq(&origin) {
-			log::trace!(
+			tracing::trace!(
 				target: "xcm::contains",
-				"RemoteAssetFromLocation asset: {asset:?}, origin: {origin:?} is not from expected {expected_origin:?}"
+				?asset,
+				?origin,
+				?expected_origin,
+				"RemoteAssetFromLocation: Asset is not from expected origin"
 			);
 			return false;
 		} else {
-			log::trace!(
+			tracing::trace!(
 				target: "xcm::contains",
-				"RemoteAssetFromLocation asset: {asset:?}, origin: {origin:?}",
+				?asset,
+				?origin,
+				"RemoteAssetFromLocation",
 			);
 		}
 
@@ -138,6 +143,7 @@ impl<AssetsAllowedNetworks: Contains<Location>, OriginLocation: Get<Location>>
 	ContainsPair<Asset, Location> for RemoteAssetFromLocation<AssetsAllowedNetworks, OriginLocation>
 {
 	fn contains(asset: &Asset, origin: &Location) -> bool {
+		tracing::trace!(target: "xcm:contains", ?asset, ?origin, "RemoteAssetFromLocation");
 		<Self as ContainsPair<Location, Location>>::contains(&asset.id.0, origin)
 	}
 }

cumulus/parachains/runtimes/assets/common/src/matching.rs

@@ -17,10 +17,10 @@ substrate-wasm-builder = { optional = true, workspace = true, default-features =
 [dependencies]
 codec = { features = ["derive"], workspace = true }
 hex-literal = { workspace = true, default-features = true }
-log = { workspace = true }
 scale-info = { features = ["derive"], workspace = true }
 serde = { optional = true, features = ["derive"], workspace = true, default-features = true }
 serde_json = { features = ["alloc"], workspace = true }
+tracing = { workspace = true }
 
 # Substrate
 frame-benchmarking = { optional = true, workspace = true }
@@ -162,7 +162,6 @@ std = [
 	"frame-system-rpc-runtime-api/std",
 	"frame-system/std",
 	"frame-try-runtime?/std",
-	"log/std",
 	"pallet-aura/std",
 	"pallet-authorship/std",
 	"pallet-balances/std",
@@ -215,6 +214,7 @@ std = [
 	"sp-version/std",
 	"substrate-wasm-builder",
 	"testnet-parachains-constants/std",
+	"tracing/std",
 	"westend-runtime-constants/std",
 	"xcm-builder/std",
 	"xcm-executor/std",

cumulus/parachains/runtimes/bridge-hubs/bridge-hub-westend/Cargo.toml

@@ -813,11 +813,11 @@ impl_runtime_apis! {
 					Ok(WeightToFee::weight_to_fee(&weight))
 				},
 				Ok(asset_id) => {
-					log::trace!(target: "xcm::xcm_runtime_apis", "query_weight_to_asset_fee - unhandled asset_id: {asset_id:?}!");
+					tracing::trace!(target: "xcm::xcm_runtime_apis", ?asset_id, "query_weight_to_asset_fee - unhandled asset_id!");
 					Err(XcmPaymentApiError::AssetNotFound)
 				},
 				Err(_) => {
-					log::trace!(target: "xcm::xcm_runtime_apis", "query_weight_to_asset_fee - failed to convert asset: {asset:?}!");
+					tracing::trace!(target: "xcm::xcm_runtime_apis", ?asset, "query_weight_to_asset_fee - failed to convert asset!");
 					Err(XcmPaymentApiError::VersionedConversionFailed)
 				}
 			}
@@ -1163,12 +1163,15 @@ impl_runtime_apis! {
 						alloc::boxed::Box::new(bridge_to_rococo_config::BridgeHubRococoLocation::get()),
 						XCM_VERSION,
 					).map_err(|e| {
-						log::error!(
-							"Failed to dispatch `force_xcm_version({:?}, {:?}, {:?})`, error: {:?}",
-							RuntimeOrigin::root(),
-							bridge_to_rococo_config::BridgeHubRococoLocation::get(),
-							XCM_VERSION,
-							e
+						let origin = RuntimeOrigin::root();
+						let bridge = bridge_to_rococo_config::BridgeHubRococoLocation::get();
+						tracing::error!(
+							target: "xcm::export_message_origin_and_destination",
+							?origin,
+							?bridge,
+							?XCM_VERSION,
+							?e,
+							"Failed to dispatch `force_xcm_version`",
 						);
 						BenchmarkError::Stop("XcmVersion was not stored!")
 					})?;
@@ -1198,11 +1201,12 @@ impl_runtime_apis! {
 						bp_messages::LegacyLaneId([1, 2, 3, 4]),
 						true,
 					).map_err(|e| {
-						log::error!(
-							"Failed to `XcmOverBridgeHubRococo::open_bridge`({:?}, {:?})`, error: {:?}",
-							sibling_parachain_location,
-							bridge_destination_universal_location,
-							e
+						tracing::error!(
+							target: "xcm::export_message_origin_and_destination",
+							?sibling_parachain_location,
+							?bridge_destination_universal_location,
+							?e,
+							"Failed to `XcmOverBridgeHubRococo::open_bridge`",
 						);
 						BenchmarkError::Stop("Bridge was not opened!")
 					})?;

cumulus/parachains/runtimes/bridge-hubs/bridge-hub-westend/src/lib.rs

@@ -123,7 +123,9 @@ pub type XcmOriginToTransactDispatchOrigin = (
 pub struct ParentOrParentsPlurality;
 impl Contains<Location> for ParentOrParentsPlurality {
 	fn contains(location: &Location) -> bool {
-		matches!(location.unpack(), (1, []) | (1, [Plurality { .. }]))
+		let result = matches!(location.unpack(), (1, []) | (1, [Plurality { .. }]));
+		tracing::trace!(target: "xcm::contains", ?location, ?result, "ParentOrParentsPlurality matches");
+		result
 	}
 }
 
@@ -300,6 +302,7 @@ impl<WaivedLocations: Contains<Location>, FeeHandler: HandleFee> FeeManager
 	}
 
 	fn handle_fee(fee: Assets, context: Option<&XcmContext>, reason: FeeReason) {
+		tracing::trace!(target: "xcm::handle_fee", ?fee, ?context, ?reason, "FeeManager handle_fee");
 		FeeHandler::handle_fee(fee, context, reason);
 	}
 }