From b20be7c11733be65332518fb542e452e3bbd7eb7 Mon Sep 17 00:00:00 2001 From: Ayevbeosa Iyamu Date: Tue, 15 Oct 2024 11:14:34 +0100 Subject: [PATCH] pallet-xcm: added useful error logs (#2408) (#4982) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Added error logs in pallet-xcm to help in debugging, fixes #2408 ## TODO - [x] change `log::error` to `tracing::error` format for `xcm-executor` - [x] check existing logs, e.g. this one can be extended with more info `tracing::error!(target: "xcm::reanchor", ?error, "Failed reanchoring with error");` - [x] use `tracing` instead of `log` for `pallet-xcm/src/lib.rs` --------- Co-authored-by: Ayevbeosa Iyamu Co-authored-by: Adrian Catangiu Co-authored-by: Francisco Aguirre Co-authored-by: Branislav Kontur Co-authored-by: Bastian Köcher --- Cargo.lock | 2 +- polkadot/xcm/pallet-xcm/Cargo.toml | 4 +- polkadot/xcm/pallet-xcm/src/benchmarking.rs | 8 +- polkadot/xcm/pallet-xcm/src/lib.rs | 192 ++++++++++++-------- polkadot/xcm/pallet-xcm/src/migration.rs | 6 +- polkadot/xcm/xcm-executor/src/lib.rs | 42 +++-- prdoc/pr_4982.prdoc | 13 ++ 7 files changed, 168 insertions(+), 99 deletions(-) create mode 100644 prdoc/pr_4982.prdoc diff --git a/Cargo.lock b/Cargo.lock index a5aa286485f6..360e89d8ad89 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -12951,7 +12951,6 @@ dependencies = [ "frame-benchmarking", "frame-support", "frame-system", - "log", "pallet-assets", "pallet-balances", "parity-scale-codec", @@ -12965,6 +12964,7 @@ dependencies = [ "staging-xcm", "staging-xcm-builder", "staging-xcm-executor", + "tracing", "xcm-runtime-apis", ] diff --git a/polkadot/xcm/pallet-xcm/Cargo.toml b/polkadot/xcm/pallet-xcm/Cargo.toml index ed4b441d7c33..4d44d75e34dd 100644 --- a/polkadot/xcm/pallet-xcm/Cargo.toml +++ b/polkadot/xcm/pallet-xcm/Cargo.toml @@ -14,7 +14,7 @@ bounded-collections = { workspace = true } codec = { features = ["derive"], workspace = true } scale-info = { features = ["derive"], workspace = true } serde = { optional = true, features = ["derive"], workspace = true, default-features = true } -log = { workspace = true } +tracing = { workspace = true } frame-support = { workspace = true } frame-system = { workspace = true } @@ -44,13 +44,13 @@ std = [ "frame-benchmarking?/std", "frame-support/std", "frame-system/std", - "log/std", "pallet-balances/std", "scale-info/std", "serde", "sp-core/std", "sp-io/std", "sp-runtime/std", + "tracing/std", "xcm-builder/std", "xcm-executor/std", "xcm-runtime-apis/std", diff --git a/polkadot/xcm/pallet-xcm/src/benchmarking.rs b/polkadot/xcm/pallet-xcm/src/benchmarking.rs index d09c81bf434e..404b9358d4d9 100644 --- a/polkadot/xcm/pallet-xcm/src/benchmarking.rs +++ b/polkadot/xcm/pallet-xcm/src/benchmarking.rs @@ -128,14 +128,14 @@ benchmarks! { &origin_location, None, ).map_err(|error| { - log::error!("Fungible asset couldn't be deposited, error: {:?}", error); + tracing::error!("Fungible asset couldn't be deposited, error: {:?}", error); BenchmarkError::Override(BenchmarkResult::from_weight(Weight::MAX)) })?; }, NonFungible(instance) => { ::AssetTransactor::deposit_asset(&asset, &origin_location, None) .map_err(|error| { - log::error!("Nonfungible asset couldn't be deposited, error: {:?}", error); + tracing::error!("Nonfungible asset couldn't be deposited, error: {:?}", error); BenchmarkError::Override(BenchmarkResult::from_weight(Weight::MAX)) })?; } @@ -178,14 +178,14 @@ benchmarks! { &origin_location, None, ).map_err(|error| { - log::error!("Fungible asset couldn't be deposited, error: {:?}", error); + tracing::error!("Fungible asset couldn't be deposited, error: {:?}", error); BenchmarkError::Override(BenchmarkResult::from_weight(Weight::MAX)) })?; }, NonFungible(instance) => { ::AssetTransactor::deposit_asset(&asset, &origin_location, None) .map_err(|error| { - log::error!("Nonfungible asset couldn't be deposited, error: {:?}", error); + tracing::error!("Nonfungible asset couldn't be deposited, error: {:?}", error); BenchmarkError::Override(BenchmarkResult::from_weight(Weight::MAX)) })?; } diff --git a/polkadot/xcm/pallet-xcm/src/lib.rs b/polkadot/xcm/pallet-xcm/src/lib.rs index ee448c3df606..d287987a96d4 100644 --- a/polkadot/xcm/pallet-xcm/src/lib.rs +++ b/polkadot/xcm/pallet-xcm/src/lib.rs @@ -307,7 +307,7 @@ pub mod pallet { message: Box::RuntimeCall>>, max_weight: Weight, ) -> Result { - log::trace!(target: "xcm::pallet_xcm::execute", "message {:?}, max_weight {:?}", message, max_weight); + tracing::trace!(target: "xcm::pallet_xcm::execute", ?message, ?max_weight); let outcome = (|| { let origin_location = T::ExecuteXcmOrigin::ensure_origin(origin)?; let mut hash = message.using_encoded(sp_io::hashing::blake2_256); @@ -330,7 +330,7 @@ pub mod pallet { Self::deposit_event(Event::Attempted { outcome: outcome.clone() }); let weight_used = outcome.weight_used(); outcome.ensure_complete().map_err(|error| { - log::error!(target: "xcm::pallet_xcm::execute", "XCM execution failed with error {:?}", error); + tracing::error!(target: "xcm::pallet_xcm::execute", ?error, "XCM execution failed with error"); Error::::LocalExecutionIncomplete.with_weight( weight_used.saturating_add( ::execute(), @@ -897,10 +897,10 @@ pub mod pallet { pub fn migrate_to_v1( ) -> frame_support::weights::Weight { let on_chain_storage_version =

::on_chain_storage_version(); - log::info!( + tracing::info!( target: "runtime::xcm", - "Running migration storage v1 for xcm with storage version {:?}", - on_chain_storage_version, + ?on_chain_storage_version, + "Running migration storage v1 for xcm with storage version", ); if on_chain_storage_version < 1 { @@ -910,18 +910,18 @@ pub mod pallet { Some(value.into()) }); StorageVersion::new(1).put::

(); - log::info!( + tracing::info!( target: "runtime::xcm", - "Running migration storage v1 for xcm with storage version {:?} was complete", - on_chain_storage_version, + ?on_chain_storage_version, + "Running migration storage v1 for xcm with storage version was complete", ); // calculate and return migration weights T::DbWeight::get().reads_writes(count as u64 + 1, count as u64 + 1) } else { - log::warn!( + tracing::warn!( target: "runtime::xcm", - "Attempted to apply migration to v1 but failed because storage version is {:?}", - on_chain_storage_version, + ?on_chain_storage_version, + "Attempted to apply migration to v1 but failed because storage version is", ); T::DbWeight::get().reads(1) } @@ -1269,10 +1269,9 @@ pub mod pallet { let beneficiary: Location = (*beneficiary).try_into().map_err(|()| Error::::BadVersion)?; let assets: Assets = (*assets).try_into().map_err(|()| Error::::BadVersion)?; - log::debug!( + tracing::debug!( target: "xcm::pallet_xcm::transfer_assets", - "origin {:?}, dest {:?}, beneficiary {:?}, assets {:?}, fee-idx {:?}, weight_limit {:?}", - origin, dest, beneficiary, assets, fee_asset_item, weight_limit, + ?origin, ?dest, ?beneficiary, ?assets, ?fee_asset_item, ?weight_limit, ); ensure!(assets.len() <= MAX_ASSETS_FOR_TRANSFER, Error::::TooManyAssets); @@ -1307,7 +1306,7 @@ pub mod pallet { beneficiary: Box, ) -> DispatchResult { let origin_location = T::ExecuteXcmOrigin::ensure_origin(origin)?; - log::debug!(target: "xcm::pallet_xcm::claim_assets", "origin: {:?}, assets: {:?}, beneficiary: {:?}", origin_location, assets, beneficiary); + tracing::debug!(target: "xcm::pallet_xcm::claim_assets", ?origin_location, ?assets, ?beneficiary); // Extract version from `assets`. let assets_version = assets.identify_version(); let assets: Assets = (*assets).try_into().map_err(|()| Error::::BadVersion)?; @@ -1330,7 +1329,7 @@ pub mod pallet { weight, ); outcome.ensure_complete().map_err(|error| { - log::error!(target: "xcm::pallet_xcm::claim_assets", "XCM execution failed with error: {:?}", error); + tracing::error!(target: "xcm::pallet_xcm::claim_assets", ?error, "XCM execution failed with error"); Error::::LocalExecutionIncomplete })?; Ok(()) @@ -1403,11 +1402,10 @@ pub mod pallet { (*remote_fees_id).try_into().map_err(|()| Error::::BadVersion)?; let remote_xcm: Xcm<()> = (*custom_xcm_on_dest).try_into().map_err(|()| Error::::BadVersion)?; - log::debug!( + tracing::debug!( target: "xcm::pallet_xcm::transfer_assets_using_type_and_then", - "origin {origin_location:?}, dest {dest:?}, assets {assets:?} through {assets_transfer_type:?}, \ - remote_fees_id {fees_id:?} through {fees_transfer_type:?}, \ - custom_xcm_on_dest {remote_xcm:?}, weight-limit {weight_limit:?}", + ?origin_location, ?dest, ?assets, ?assets_transfer_type, ?fees_id, ?fees_transfer_type, + ?remote_xcm, ?weight_limit, ); let assets = assets.into_inner(); @@ -1568,10 +1566,9 @@ impl Pallet { let beneficiary: Location = (*beneficiary).try_into().map_err(|()| Error::::BadVersion)?; let assets: Assets = (*assets).try_into().map_err(|()| Error::::BadVersion)?; - log::debug!( + tracing::debug!( target: "xcm::pallet_xcm::do_reserve_transfer_assets", - "origin {:?}, dest {:?}, beneficiary {:?}, assets {:?}, fee-idx {:?}", - origin_location, dest, beneficiary, assets, fee_asset_item, + ?origin_location, ?dest, ?beneficiary, ?assets, ?fee_asset_item, ); ensure!(assets.len() <= MAX_ASSETS_FOR_TRANSFER, Error::::TooManyAssets); @@ -1615,10 +1612,9 @@ impl Pallet { let beneficiary: Location = (*beneficiary).try_into().map_err(|()| Error::::BadVersion)?; let assets: Assets = (*assets).try_into().map_err(|()| Error::::BadVersion)?; - log::debug!( + tracing::debug!( target: "xcm::pallet_xcm::do_teleport_assets", - "origin {:?}, dest {:?}, beneficiary {:?}, assets {:?}, fee-idx {:?}, weight_limit {:?}", - origin_location, dest, beneficiary, assets, fee_asset_item, weight_limit, + ?origin_location, ?dest, ?beneficiary, ?assets, ?fee_asset_item, ?weight_limit, ); ensure!(assets.len() <= MAX_ASSETS_FOR_TRANSFER, Error::::TooManyAssets); @@ -1719,11 +1715,9 @@ impl Pallet { fees: FeesHandling, weight_limit: WeightLimit, ) -> Result<(Xcm<::RuntimeCall>, Option>), Error> { - log::debug!( + tracing::debug!( target: "xcm::pallet_xcm::build_xcm_transfer_type", - "origin {:?}, dest {:?}, beneficiary {:?}, assets {:?}, transfer_type {:?}, \ - fees_handling {:?}, weight_limit: {:?}", - origin, dest, beneficiary, assets, transfer_type, fees, weight_limit, + ?origin, ?dest, ?beneficiary, ?assets, ?transfer_type, ?fees, ?weight_limit, ); match transfer_type { TransferType::LocalReserve => Self::local_reserve_transfer_programs( @@ -1778,10 +1772,9 @@ impl Pallet { mut local_xcm: Xcm<::RuntimeCall>, remote_xcm: Option>, ) -> DispatchResult { - log::debug!( + tracing::debug!( target: "xcm::pallet_xcm::execute_xcm_transfer", - "origin {:?}, dest {:?}, local_xcm {:?}, remote_xcm {:?}", - origin, dest, local_xcm, remote_xcm, + ?origin, ?dest, ?local_xcm, ?remote_xcm, ); let weight = @@ -1795,10 +1788,10 @@ impl Pallet { weight, ); Self::deposit_event(Event::Attempted { outcome: outcome.clone() }); - outcome.ensure_complete().map_err(|error| { - log::error!( + outcome.clone().ensure_complete().map_err(|error| { + tracing::error!( target: "xcm::pallet_xcm::execute_xcm_transfer", - "XCM execution failed with error {:?}", error + ?error, "XCM execution failed with error with outcome: {:?}", outcome ); Error::::LocalExecutionIncomplete })?; @@ -1807,10 +1800,10 @@ impl Pallet { let (ticket, price) = validate_send::(dest.clone(), remote_xcm.clone()) .map_err(Error::::from)?; if origin != Here.into_location() { - Self::charge_fees(origin.clone(), price).map_err(|error| { - log::error!( + Self::charge_fees(origin.clone(), price.clone()).map_err(|error| { + tracing::error!( target: "xcm::pallet_xcm::execute_xcm_transfer", - "Unable to charge fee with error {:?}", error + ?error, ?price, ?origin, "Unable to charge fee", ); Error::::FeesNotMet })?; @@ -1836,7 +1829,10 @@ impl Pallet { // no custom fees instructions, they are batched together with `assets` transfer; // BuyExecution happens after receiving all `assets` let reanchored_fees = - fees.reanchored(&dest, &context).map_err(|_| Error::::CannotReanchor)?; + fees.reanchored(&dest, &context).map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::add_fees_to_xcm", ?e, ?dest, ?context, "Failed to re-anchor fees"); + Error::::CannotReanchor + })?; // buy execution using `fees` batched together with above `reanchored_assets` remote.inner_mut().push(BuyExecution { fees: reanchored_fees, weight_limit }); }, @@ -1901,7 +1897,10 @@ impl Pallet { let mut reanchored_assets = assets.clone(); reanchored_assets .reanchor(&dest, &context) - .map_err(|_| Error::::CannotReanchor)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::local_reserve_transfer_programs", ?e, ?dest, ?context, "Failed to re-anchor assets"); + Error::::CannotReanchor + })?; // XCM instructions to be executed on local chain let mut local_execute_xcm = Xcm(vec![ @@ -1948,7 +1947,10 @@ impl Pallet { let reanchored_fees = fees .clone() .reanchored(&dest, &context) - .map_err(|_| Error::::CannotReanchor)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::destination_reserve_fees_instructions", ?e, ?dest,?context, "Failed to re-anchor fees"); + Error::::CannotReanchor + })?; let fees: Assets = fees.into(); let local_execute_xcm = Xcm(vec![ @@ -1992,7 +1994,10 @@ impl Pallet { let mut reanchored_assets = assets.clone(); reanchored_assets .reanchor(&dest, &context) - .map_err(|_| Error::::CannotReanchor)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::destination_reserve_transfer_programs", ?e, ?dest, ?context, "Failed to re-anchor assets"); + Error::::CannotReanchor + })?; // XCM instructions to be executed on local chain let mut local_execute_xcm = Xcm(vec![ @@ -2046,13 +2051,22 @@ impl Pallet { // identifies fee item as seen by `reserve` - to be used at reserve chain let reserve_fees = fees_half_1 .reanchored(&reserve, &context) - .map_err(|_| Error::::CannotReanchor)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::remote_reserve_transfer_program", ?e, ?reserve, ?context, "Failed to re-anchor reserve_fees"); + Error::::CannotReanchor + })?; // identifies fee item as seen by `dest` - to be used at destination chain let dest_fees = fees_half_2 .reanchored(&dest, &context) - .map_err(|_| Error::::CannotReanchor)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::remote_reserve_transfer_program", ?e, ?dest, ?context, "Failed to re-anchor dest_fees"); + Error::::CannotReanchor + })?; // identifies `dest` as seen by `reserve` - let dest = dest.reanchored(&reserve, &context).map_err(|_| Error::::CannotReanchor)?; + let dest = dest.reanchored(&reserve, &context).map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::remote_reserve_transfer_program", ?e, ?reserve, ?context, "Failed to re-anchor dest"); + Error::::CannotReanchor + })?; // xcm to be executed at dest let mut xcm_on_dest = Xcm(vec![BuyExecution { fees: dest_fees, weight_limit: weight_limit.clone() }]); @@ -2098,7 +2112,10 @@ impl Pallet { let reanchored_fees = fees .clone() .reanchored(&dest, &context) - .map_err(|_| Error::::CannotReanchor)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::teleport_fees_instructions", ?e, ?dest, ?context, "Failed to re-anchor fees"); + Error::::CannotReanchor + })?; // XcmContext irrelevant in teleports checks let dummy_context = @@ -2112,7 +2129,10 @@ impl Pallet { &fees, &dummy_context, ) - .map_err(|_| Error::::CannotCheckOutTeleport)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::teleport_fees_instructions", ?e, ?fees, ?dest, "Failed can_check_out"); + Error::::CannotCheckOutTeleport + })?; // safe to do this here, we're in a transactional call that will be reverted on any // errors down the line ::AssetTransactor::check_out( @@ -2163,7 +2183,10 @@ impl Pallet { let mut reanchored_assets = assets.clone(); reanchored_assets .reanchor(&dest, &context) - .map_err(|_| Error::::CannotReanchor)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::teleport_assets_program", ?e, ?dest, ?context, "Failed to re-anchor asset"); + Error::::CannotReanchor + })?; // XcmContext irrelevant in teleports checks let dummy_context = @@ -2178,7 +2201,10 @@ impl Pallet { asset, &dummy_context, ) - .map_err(|_| Error::::CannotCheckOutTeleport)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::teleport_assets_program", ?e, ?asset, ?dest, "Failed can_check_out asset"); + Error::::CannotCheckOutTeleport + })?; } for asset in assets.inner() { // safe to do this here, we're in a transactional call that will be reverted on any @@ -2448,10 +2474,17 @@ impl Pallet { } else { None }; - log::debug!(target: "xcm::send_xcm", "dest: {:?}, message: {:?}", &dest, &message); + tracing::debug!(target: "xcm::send_xcm", "{:?}, {:?}", dest.clone(), message.clone()); let (ticket, price) = validate_send::(dest, message)?; if let Some(fee_payer) = maybe_fee_payer { - Self::charge_fees(fee_payer, price).map_err(|_| SendError::Fees)?; + Self::charge_fees(fee_payer, price).map_err(|e| { + tracing::error!( + target: "xcm::pallet_xcm::send_xcm", + ?e, + "Charging fees failed with error", + ); + SendError::Fees + })?; } T::XcmRouter::deliver(ticket) } @@ -2512,18 +2545,16 @@ impl Pallet { XcmConfig: xcm_executor::Config, { let origin_location: Location = origin_location.try_into().map_err(|error| { - log::error!( + tracing::error!( target: "xcm::DryRunApi::dry_run_xcm", - "Location version conversion failed with error: {:?}", - error, + ?error, "Location version conversion failed with error" ); XcmDryRunApiError::VersionedConversionFailed })?; let xcm: Xcm = xcm.try_into().map_err(|error| { - log::error!( + tracing::error!( target: "xcm::DryRunApi::dry_run_xcm", - "Xcm version conversion failed with error {:?}", - error, + ?error, "Xcm version conversion failed with error" ); XcmDryRunApiError::VersionedConversionFailed })?; @@ -2560,11 +2591,14 @@ impl Pallet { } pub fn query_xcm_weight(message: VersionedXcm<()>) -> Result { - let message = Xcm::<()>::try_from(message) - .map_err(|_| XcmPaymentApiError::VersionedConversionFailed)?; + let message = Xcm::<()>::try_from(message.clone()) + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::query_xcm_weight", ?e, ?message, "Failed to convert versioned message"); + XcmPaymentApiError::VersionedConversionFailed + })?; - T::Weigher::weight(&mut message.into()).map_err(|()| { - log::error!(target: "xcm::pallet_xcm::query_xcm_weight", "Error when querying XCM weight"); + T::Weigher::weight(&mut message.clone().into()).map_err(|()| { + tracing::error!(target: "xcm::pallet_xcm::query_xcm_weight", ?message, "Error when querying XCM weight"); XcmPaymentApiError::WeightNotComputable }) } @@ -2575,21 +2609,31 @@ impl Pallet { ) -> Result { let result_version = destination.identify_version().max(message.identify_version()); - let destination = destination + let destination: Location = destination + .clone() .try_into() - .map_err(|_| XcmPaymentApiError::VersionedConversionFailed)?; + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::query_delivery_fees", ?e, ?destination, "Failed to convert versioned destination"); + XcmPaymentApiError::VersionedConversionFailed + })?; - let message = - message.try_into().map_err(|_| XcmPaymentApiError::VersionedConversionFailed)?; + let message: Xcm<()> = + message.clone().try_into().map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::query_delivery_fees", ?e, ?message, "Failed to convert versioned message"); + XcmPaymentApiError::VersionedConversionFailed + })?; - let (_, fees) = validate_send::(destination, message).map_err(|error| { - log::error!(target: "xcm::pallet_xcm::query_delivery_fees", "Error when querying delivery fees: {:?}", error); + let (_, fees) = validate_send::(destination.clone(), message.clone()).map_err(|error| { + tracing::error!(target: "xcm::pallet_xcm::query_delivery_fees", ?error, ?destination, ?message, "Failed to validate send to destination"); XcmPaymentApiError::Unroutable })?; VersionedAssets::from(fees) .into_version(result_version) - .map_err(|_| XcmPaymentApiError::VersionedConversionFailed) + .map_err(|e| { + tracing::error!(target: "xcm::pallet_xcm::query_delivery_fees", ?e, ?result_version, "Failed to convert fees into version"); + XcmPaymentApiError::VersionedConversionFailed + }) } /// Create a new expectation of a query response with the querier being here. @@ -2673,10 +2717,9 @@ impl 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: &Location) { - log::trace!( + tracing::trace!( target: "xcm::pallet_xcm::note_unknown_version", - "XCM version is unknown for destination: {:?}", - dest, + ?dest, "XCM version is unknown for destination" ); let versioned_dest = VersionedLocation::from(dest.clone()); VersionDiscoveryQueue::::mutate(|q| { @@ -2944,10 +2987,9 @@ impl WrapVersion for Pallet { SafeXcmVersion::::get() }) .ok_or_else(|| { - log::trace!( + tracing::trace!( target: "xcm::pallet_xcm::wrap_version", - "Could not determine a version to wrap XCM for destination: {:?}", - dest, + ?dest, "Could not determine a version to wrap XCM for destination", ); () }) diff --git a/polkadot/xcm/pallet-xcm/src/migration.rs b/polkadot/xcm/pallet-xcm/src/migration.rs index 0aec97ab4105..2c5b2620f535 100644 --- a/polkadot/xcm/pallet-xcm/src/migration.rs +++ b/polkadot/xcm/pallet-xcm/src/migration.rs @@ -40,7 +40,7 @@ pub mod v1 { let mut weight = T::DbWeight::get().reads(1); if StorageVersion::get::>() != 0 { - log::warn!("skipping v1, should be removed"); + tracing::warn!("skipping v1, should be removed"); return weight } @@ -50,13 +50,13 @@ pub mod v1 { let translate = |pre: (u64, u64, u32)| -> Option<(u64, Weight, u32)> { weight.saturating_accrue(T::DbWeight::get().reads_writes(1, 1)); let translated = (pre.0, Weight::from_parts(pre.1, DEFAULT_PROOF_SIZE), pre.2); - log::info!("Migrated VersionNotifyTarget {:?} to {:?}", pre, translated); + tracing::info!("Migrated VersionNotifyTarget {:?} to {:?}", pre, translated); Some(translated) }; VersionNotifyTargets::::translate_values(translate); - log::info!("v1 applied successfully"); + tracing::info!("v1 applied successfully"); weight.saturating_accrue(T::DbWeight::get().writes(1)); StorageVersion::new(1).put::>(); weight diff --git a/polkadot/xcm/xcm-executor/src/lib.rs b/polkadot/xcm/xcm-executor/src/lib.rs index 14920f36445b..71985360b7d3 100644 --- a/polkadot/xcm/xcm-executor/src/lib.rs +++ b/polkadot/xcm/xcm-executor/src/lib.rs @@ -495,7 +495,7 @@ impl XcmExecutor { self.calculate_asset_for_delivery_fees(asset_needed_for_fees.clone()); tracing::trace!(target: "xcm::fees", ?asset_to_pay_for_fees); // We withdraw or take from holding the asset the user wants to use for fee payment. - let withdrawn_fee_asset = if self.fees_mode.jit_withdraw { + let withdrawn_fee_asset: AssetsInHolding = if self.fees_mode.jit_withdraw { let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?; Config::AssetTransactor::withdraw_asset( &asset_to_pay_for_fees, @@ -508,7 +508,10 @@ impl XcmExecutor { let assets_taken_from_holding_to_pay_delivery_fees = self .holding .try_take(asset_to_pay_for_fees.clone().into()) - .map_err(|_| XcmError::NotHoldingFees)?; + .map_err(|e| { + tracing::error!(target: "xcm::fees", ?e, ?asset_to_pay_for_fees, "Failed to take asset_to_pay_for_fees from holding"); + XcmError::NotHoldingFees + })?; tracing::trace!(target: "xcm::fees", ?assets_taken_from_holding_to_pay_delivery_fees); let mut iter = assets_taken_from_holding_to_pay_delivery_fees.fungible_assets_iter(); let asset = iter.next().ok_or(XcmError::NotHoldingFees)?; @@ -518,15 +521,14 @@ impl XcmExecutor { let paid = if asset_to_pay_for_fees.id != asset_needed_for_fees.id { let swapped_asset: Assets = Config::AssetExchanger::exchange_asset( self.origin_ref(), - withdrawn_fee_asset, + withdrawn_fee_asset.clone().into(), &asset_needed_for_fees.clone().into(), false, ) .map_err(|given_assets| { tracing::error!( target: "xcm::fees", - ?given_assets, - "Swap was deemed necessary but couldn't be done", + ?given_assets, "Swap was deemed necessary but couldn't be done for withdrawn_fee_asset: {:?} and asset_needed_for_fees: {:?}", withdrawn_fee_asset.clone(), asset_needed_for_fees, ); XcmError::FeesNotMet })? @@ -587,8 +589,10 @@ impl XcmExecutor { Ok(match local_querier { None => None, Some(q) => Some( - q.reanchored(&destination, &Config::UniversalLocation::get()) - .map_err(|_| XcmError::ReanchorFailed)?, + q.reanchored(&destination, &Config::UniversalLocation::get()).map_err(|e| { + tracing::error!(target: "xcm::xcm_executor::to_querier", ?e, ?destination, "Failed to re-anchor local_querier"); + XcmError::ReanchorFailed + })?, ), }) } @@ -617,7 +621,7 @@ impl XcmExecutor { let reanchor_context = Config::UniversalLocation::get(); let reanchored = reanchorable.reanchored(&destination, &reanchor_context).map_err(|error| { - tracing::error!(target: "xcm::reanchor", ?error, "Failed reanchoring with error"); + tracing::error!(target: "xcm::reanchor", ?error, ?destination, ?reanchor_context, "Failed reanchoring with error."); XcmError::ReanchorFailed })?; Ok((reanchored, reanchor_context)) @@ -923,7 +927,10 @@ impl XcmExecutor { .as_mut() .ok_or(XcmError::BadOrigin)? .append_with(who) - .map_err(|_| XcmError::LocationFull), + .map_err(|e| { + tracing::error!(target: "xcm::process_instruction::descend_origin", ?e, "Failed to append junctions"); + XcmError::LocationFull + }), ClearOrigin => { self.context.origin = None; Ok(()) @@ -1087,7 +1094,10 @@ impl XcmExecutor { tracing::trace!(target: "xcm::executor::BuyExecution", asset_used_for_fees = ?self.asset_used_for_fees); // pay for `weight` using up to `fees` of the holding register. let max_fee = - self.holding.try_take(fees.into()).map_err(|_| XcmError::NotHoldingFees)?; + self.holding.try_take(fees.clone().into()).map_err(|e| { + tracing::error!(target: "xcm::process_instruction::buy_execution", ?e, ?fees, "Failed to take fees from holding"); + XcmError::NotHoldingFees + })?; let result = || -> Result<(), XcmError> { let unspent = self.trader.buy_weight(weight, max_fee, &self.context)?; self.holding.subsume_assets(unspent); @@ -1150,7 +1160,10 @@ impl XcmExecutor { Ok(()) }, ExpectAsset(assets) => - self.holding.ensure_contains(&assets).map_err(|_| XcmError::ExpectationFalse), + self.holding.ensure_contains(&assets).map_err(|e| { + tracing::error!(target: "xcm::process_instruction::expect_asset", ?e, ?assets, "assets not contained in holding"); + XcmError::ExpectationFalse + }), ExpectOrigin(origin) => { ensure!(self.context.origin == origin, XcmError::ExpectationFalse); Ok(()) @@ -1272,9 +1285,10 @@ impl XcmExecutor { let (remote_asset, context) = Self::try_reanchor(asset.clone(), &unlocker)?; let lock_ticket = Config::AssetLocker::prepare_lock(unlocker.clone(), asset, origin.clone())?; - let owner = origin - .reanchored(&unlocker, &context) - .map_err(|_| XcmError::ReanchorFailed)?; + let owner = origin.reanchored(&unlocker, &context).map_err(|e| { + tracing::error!(target: "xcm::xcm_executor::process_instruction", ?e, ?unlocker, ?context, "Failed to re-anchor origin"); + XcmError::ReanchorFailed + })?; let msg = Xcm::<()>(vec![NoteUnlockable { asset: remote_asset, owner }]); let (ticket, price) = validate_send::(unlocker, msg)?; self.take_fee(price, FeeReason::LockAsset)?; diff --git a/prdoc/pr_4982.prdoc b/prdoc/pr_4982.prdoc new file mode 100644 index 000000000000..9e6d103a0ad8 --- /dev/null +++ b/prdoc/pr_4982.prdoc @@ -0,0 +1,13 @@ +title: Add useful error logs in pallet-xcm + +doc: + - audience: Runtime Dev + description: | + This PR adds error logs to assist in debugging pallet-xcm. + Additionally, it replaces the usage of `log` with `tracing`. + +crates: + - name: staging-xcm-executor + bump: patch + - name: pallet-xcm + bump: patch