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

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

@@ -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/src/benchmarks.rs

@@ -35,9 +35,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/foreign_creators.rs

@@ -42,8 +42,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/fungible_conversion.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/matching.rs

@@ -33,8 +33,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
 	}
 }
 
@@ -47,6 +48,7 @@ impl<SelfParaId: Get<ParaId>, L: TryFrom<Location> + TryInto<Location> + Clone>
 	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
@@ -74,6 +76,7 @@ impl<
 	> 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 +89,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 +117,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 +142,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/bridge-hubs/bridge-hub-westend/Cargo.toml

@@ -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/src/lib.rs

@@ -795,11 +795,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)
 				}
 			}
@@ -1144,12 +1144,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!")
 					})?;
@@ -1179,11 +1182,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/xcm_config.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);
 	}
 }

polkadot/xcm/xcm-builder/Cargo.toml

@@ -16,14 +16,14 @@ codec = { features = ["derive"], workspace = true }
 frame-support = { workspace = true }
 frame-system = { workspace = true }
 impl-trait-for-tuples = { workspace = true }
-log = { workspace = true }
 pallet-asset-conversion = { workspace = true }
 pallet-transaction-payment = { workspace = true }
 scale-info = { features = ["derive"], workspace = true }
 sp-arithmetic = { workspace = true }
 sp-io = { workspace = true }
 sp-runtime = { workspace = true }
 sp-weights = { workspace = true }
+tracing = { workspace = true }
 xcm = { workspace = true }
 xcm-executor = { workspace = true }
 
@@ -65,7 +65,6 @@ std = [
 	"codec/std",
 	"frame-support/std",
 	"frame-system/std",
-	"log/std",
 	"pallet-asset-conversion/std",
 	"pallet-transaction-payment/std",
 	"polkadot-parachain-primitives/std",
@@ -75,6 +74,7 @@ std = [
 	"sp-io/std",
 	"sp-runtime/std",
 	"sp-weights/std",
+	"tracing/std",
 	"xcm-executor/std",
 	"xcm/std",
 ]