diff --git a/Cargo.lock b/Cargo.lock index f56868d72d..01a67a8031 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -19143,6 +19143,7 @@ version = "1.0.0" name = "staging-xcm" version = "1.0.0" dependencies = [ + "array-bytes 6.1.0", "bounded-collections", "derivative", "environmental", diff --git a/cumulus/parachains/runtimes/coretime/coretime-rococo/src/lib.rs b/cumulus/parachains/runtimes/coretime/coretime-rococo/src/lib.rs index 2e7889ca01..2d50a17c3f 100644 --- a/cumulus/parachains/runtimes/coretime/coretime-rococo/src/lib.rs +++ b/cumulus/parachains/runtimes/coretime/coretime-rococo/src/lib.rs @@ -121,7 +121,7 @@ pub const VERSION: RuntimeVersion = RuntimeVersion { spec_name: create_runtime_str!("coretime-rococo"), impl_name: create_runtime_str!("coretime-rococo"), authoring_version: 1, - spec_version: 1_005_002, + spec_version: 1_005_003, impl_version: 0, apis: RUNTIME_API_VERSIONS, transaction_version: 0, diff --git a/polkadot/xcm/Cargo.toml b/polkadot/xcm/Cargo.toml index 235a4b204c..024e788b87 100644 --- a/polkadot/xcm/Cargo.toml +++ b/polkadot/xcm/Cargo.toml @@ -10,6 +10,7 @@ license.workspace = true workspace = true [dependencies] +array-bytes = "6.1" bounded-collections = { version = "0.1.9", default-features = false, features = ["serde"] } derivative = { version = "2.2.0", default-features = false, features = ["use_core"] } impl-trait-for-tuples = "0.2.2" diff --git a/polkadot/xcm/src/double_encoded.rs b/polkadot/xcm/src/double_encoded.rs index 45856f657d..320cccf9b1 100644 --- a/polkadot/xcm/src/double_encoded.rs +++ b/polkadot/xcm/src/double_encoded.rs @@ -47,7 +47,7 @@ impl Eq for DoubleEncoded {} impl core::fmt::Debug for DoubleEncoded { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { - self.encoded.fmt(f) + array_bytes::bytes2hex("0x", &self.encoded).fmt(f) } } diff --git a/polkadot/xcm/xcm-builder/src/process_xcm_message.rs b/polkadot/xcm/xcm-builder/src/process_xcm_message.rs index 330ff40aac..7334bcd201 100644 --- a/polkadot/xcm/xcm-builder/src/process_xcm_message.rs +++ b/polkadot/xcm/xcm-builder/src/process_xcm_message.rs @@ -16,16 +16,15 @@ //! Implementation of `ProcessMessage` for an `ExecuteXcm` implementation. -use frame_support::{ - ensure, - traits::{ProcessMessage, ProcessMessageError}, -}; +use frame_support::traits::{ProcessMessage, ProcessMessageError}; use parity_scale_codec::{Decode, FullCodec, MaxEncodedLen}; use scale_info::TypeInfo; use sp_std::{fmt::Debug, marker::PhantomData}; use sp_weights::{Weight, WeightMeter}; use xcm::prelude::*; +const LOG_TARGET: &str = "xcm::process-message"; + /// A message processor that delegates execution to an `XcmExecutor`. pub struct ProcessXcmMessage( PhantomData<(MessageOrigin, XcmExecutor, Call)>, @@ -45,21 +44,68 @@ impl< meter: &mut WeightMeter, id: &mut XcmHash, ) -> Result { - let versioned_message = VersionedXcm::::decode(&mut &message[..]) - .map_err(|_| ProcessMessageError::Corrupt)?; - let message = Xcm::::try_from(versioned_message) - .map_err(|_| ProcessMessageError::Unsupported)?; - let pre = XcmExecutor::prepare(message).map_err(|_| ProcessMessageError::Unsupported)?; + let versioned_message = VersionedXcm::::decode(&mut &message[..]).map_err(|e| { + log::trace!( + target: LOG_TARGET, + "`VersionedXcm` failed to decode: {e:?}", + ); + + ProcessMessageError::Corrupt + })?; + let message = Xcm::::try_from(versioned_message).map_err(|_| { + log::trace!( + target: LOG_TARGET, + "Failed to convert `VersionedXcm` into `XcmV3`.", + ); + + ProcessMessageError::Unsupported + })?; + let pre = XcmExecutor::prepare(message).map_err(|_| { + log::trace!( + target: LOG_TARGET, + "Failed to prepare message.", + ); + + ProcessMessageError::Unsupported + })?; // The worst-case weight: let required = pre.weight_of(); - ensure!(meter.can_consume(required), ProcessMessageError::Overweight(required)); + if !meter.can_consume(required) { + log::trace!( + target: LOG_TARGET, + "Xcm required {required} more than remaining {}", + meter.remaining(), + ); + + return Err(ProcessMessageError::Overweight(required)) + } let (consumed, result) = match XcmExecutor::execute(origin.into(), pre, id, Weight::zero()) { - Outcome::Complete(w) => (w, Ok(true)), - Outcome::Incomplete(w, _) => (w, Ok(false)), + Outcome::Complete(w) => { + log::trace!( + target: LOG_TARGET, + "XCM message execution complete, used weight: {w}", + ); + (w, Ok(true)) + }, + Outcome::Incomplete(w, e) => { + log::trace!( + target: LOG_TARGET, + "XCM message execution incomplete, used weight: {w}, error: {e:?}", + ); + + (w, Ok(false)) + }, // In the error-case we assume the worst case and consume all possible weight. - Outcome::Error(_) => (required, Err(ProcessMessageError::Unsupported)), + Outcome::Error(e) => { + log::trace!( + target: LOG_TARGET, + "XCM message execution error: {e:?}", + ); + + (required, Err(ProcessMessageError::Unsupported)) + }, }; meter.consume(consumed); result diff --git a/polkadot/xcm/xcm-builder/src/tests/mock.rs b/polkadot/xcm/xcm-builder/src/tests/mock.rs index 843c39bbfe..c1b3f0cf22 100644 --- a/polkadot/xcm/xcm-builder/src/tests/mock.rs +++ b/polkadot/xcm/xcm-builder/src/tests/mock.rs @@ -48,6 +48,7 @@ pub use xcm_executor::{ Assets, Config, }; +#[derive(Debug)] pub enum TestOrigin { Root, Relay, diff --git a/polkadot/xcm/xcm-executor/src/lib.rs b/polkadot/xcm/xcm-executor/src/lib.rs index ac256ea148..665b051c13 100644 --- a/polkadot/xcm/xcm-executor/src/lib.rs +++ b/polkadot/xcm/xcm-executor/src/lib.rs @@ -24,7 +24,7 @@ use frame_support::{ use parity_scale_codec::{Decode, Encode}; use sp_core::defer; use sp_io::hashing::blake2_128; -use sp_std::{marker::PhantomData, prelude::*}; +use sp_std::{fmt::Debug, marker::PhantomData, prelude::*}; use sp_weights::Weight; use xcm::latest::prelude::*; @@ -199,10 +199,7 @@ impl ExecuteXcm for XcmExecutor ExecuteXcm for XcmExecutor ExecuteXcm for XcmExecutor XcmExecutor { } } - #[cfg(feature = "runtime-benchmarks")] - pub fn bench_process(&mut self, xcm: Xcm) -> Result<(), ExecutorError> { - self.process(xcm) - } - - fn process(&mut self, xcm: Xcm) -> Result<(), ExecutorError> { - log::trace!( - target: "xcm::process", - "origin: {:?}, total_surplus/refunded: {:?}/{:?}, error_handler_weight: {:?}", - self.origin_ref(), - self.total_surplus, - self.total_refunded, - self.error_handler_weight, - ); - let mut result = Ok(()); - for (i, instr) in xcm.0.into_iter().enumerate() { - match &mut result { - r @ Ok(()) => { - // Initialize the recursion count only the first time we hit this code in our - // potential recursive execution. - let inst_res = recursion_count::using_once(&mut 1, || { - recursion_count::with(|count| { - if *count > RECURSION_LIMIT { - return Err(XcmError::ExceedsStackLimit) - } - *count = count.saturating_add(1); - Ok(()) - }) - // This should always return `Some`, but let's play it safe. - .unwrap_or(Ok(()))?; - - // Ensure that we always decrement the counter whenever we finish processing - // the instruction. - defer! { - recursion_count::with(|count| { - *count = count.saturating_sub(1); - }); - } - - self.process_instruction(instr) - }); - if let Err(e) = inst_res { - log::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e); - *r = Err(ExecutorError { - index: i as u32, - xcm_error: e, - weight: Weight::zero(), - }); - } - }, - Err(ref mut error) => - if let Ok(x) = Config::Weigher::instr_weight(&instr) { - error.weight.saturating_accrue(x) - }, - } - } - result - } - /// Execute any final operations after having executed the XCM message. /// This includes refunding surplus weight, trapping extra holding funds, and returning any /// errors during execution. @@ -468,6 +403,154 @@ impl XcmExecutor { Ok(()) } + fn take_fee(&mut self, fee: MultiAssets, reason: FeeReason) -> XcmResult { + if Config::FeeManager::is_waived(self.origin_ref(), reason) { + return Ok(()) + } + log::trace!( + target: "xcm::fees", + "taking fee: {:?} from origin_ref: {:?} in fees_mode: {:?} for a reason: {:?}", + fee, + self.origin_ref(), + self.fees_mode, + reason, + ); + let paid = if self.fees_mode.jit_withdraw { + let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?; + for asset in fee.inner() { + Config::AssetTransactor::withdraw_asset(&asset, origin, Some(&self.context))?; + } + fee + } else { + self.holding.try_take(fee.into()).map_err(|_| XcmError::NotHoldingFees)?.into() + }; + Config::FeeManager::handle_fee(paid, Some(&self.context), reason); + Ok(()) + } + + /// Calculates what `local_querier` would be from the perspective of `destination`. + fn to_querier( + local_querier: Option, + destination: &MultiLocation, + ) -> Result, XcmError> { + Ok(match local_querier { + None => None, + Some(q) => Some( + q.reanchored(&destination, Config::UniversalLocation::get()) + .map_err(|_| XcmError::ReanchorFailed)?, + ), + }) + } + + /// Send a bare `QueryResponse` message containing `response` informed by the given `info`. + /// + /// The `local_querier` argument is the querier (if any) specified from the *local* perspective. + fn respond( + &mut self, + local_querier: Option, + response: Response, + info: QueryResponseInfo, + fee_reason: FeeReason, + ) -> Result { + let querier = Self::to_querier(local_querier, &info.destination)?; + let QueryResponseInfo { destination, query_id, max_weight } = info; + let instruction = QueryResponse { query_id, response, max_weight, querier }; + let message = Xcm(vec![instruction]); + self.send(destination, message, fee_reason) + } + + fn try_reanchor( + asset: MultiAsset, + destination: &MultiLocation, + ) -> Result<(MultiAsset, InteriorMultiLocation), XcmError> { + let reanchor_context = Config::UniversalLocation::get(); + let asset = asset + .reanchored(&destination, reanchor_context) + .map_err(|()| XcmError::ReanchorFailed)?; + Ok((asset, reanchor_context)) + } + + fn try_reanchor_multilocation( + location: MultiLocation, + destination: &MultiLocation, + ) -> Result<(MultiLocation, InteriorMultiLocation), XcmError> { + let reanchor_context = Config::UniversalLocation::get(); + let location = location + .reanchored(&destination, reanchor_context) + .map_err(|_| XcmError::ReanchorFailed)?; + Ok((location, reanchor_context)) + } + + /// NOTE: Any assets which were unable to be reanchored are introduced into `failed_bin`. + fn reanchored( + mut assets: Assets, + dest: &MultiLocation, + maybe_failed_bin: Option<&mut Assets>, + ) -> MultiAssets { + let reanchor_context = Config::UniversalLocation::get(); + assets.reanchor(dest, reanchor_context, maybe_failed_bin); + assets.into_assets_iter().collect::>().into() + } + + #[cfg(feature = "runtime-benchmarks")] + pub fn bench_process(&mut self, xcm: Xcm) -> Result<(), ExecutorError> { + self.process(xcm) + } + + fn process(&mut self, xcm: Xcm) -> Result<(), ExecutorError> { + log::trace!( + target: "xcm::process", + "origin: {:?}, total_surplus/refunded: {:?}/{:?}, error_handler_weight: {:?}", + self.origin_ref(), + self.total_surplus, + self.total_refunded, + self.error_handler_weight, + ); + let mut result = Ok(()); + for (i, instr) in xcm.0.into_iter().enumerate() { + match &mut result { + r @ Ok(()) => { + // Initialize the recursion count only the first time we hit this code in our + // potential recursive execution. + let inst_res = recursion_count::using_once(&mut 1, || { + recursion_count::with(|count| { + if *count > RECURSION_LIMIT { + return Err(XcmError::ExceedsStackLimit) + } + *count = count.saturating_add(1); + Ok(()) + }) + // This should always return `Some`, but let's play it safe. + .unwrap_or(Ok(()))?; + + // Ensure that we always decrement the counter whenever we finish processing + // the instruction. + defer! { + recursion_count::with(|count| { + *count = count.saturating_sub(1); + }); + } + + self.process_instruction(instr) + }); + if let Err(e) = inst_res { + log::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e); + *r = Err(ExecutorError { + index: i as u32, + xcm_error: e, + weight: Weight::zero(), + }); + } + }, + Err(ref mut error) => + if let Ok(x) = Config::Weigher::instr_weight(&instr) { + error.weight.saturating_accrue(x) + }, + } + } + result + } + /// Process a single XCM instruction, mutating the state of the XCM virtual machine. fn process_instruction( &mut self, @@ -551,22 +634,81 @@ impl XcmExecutor { }, Transact { origin_kind, require_weight_at_most, mut call } => { // We assume that the Relay-chain is allowed to use transact on this parachain. - let origin = *self.origin_ref().ok_or(XcmError::BadOrigin)?; + let origin = *self.origin_ref().ok_or_else(|| { + log::trace!( + target: "xcm::process_instruction::transact", + "No origin provided", + ); + + XcmError::BadOrigin + })?; // TODO: #2841 #TRANSACTFILTER allow the trait to issue filters for the relay-chain - let message_call = call.take_decoded().map_err(|_| XcmError::FailedToDecode)?; - ensure!(Config::SafeCallFilter::contains(&message_call), XcmError::NoPermission); + let message_call = call.take_decoded().map_err(|_| { + log::trace!( + target: "xcm::process_instruction::transact", + "Failed to decode call", + ); + + XcmError::FailedToDecode + })?; + + log::trace!( + target: "xcm::process_instruction::transact", + "Processing call: {message_call:?}", + ); + + if !Config::SafeCallFilter::contains(&message_call) { + log::trace!( + target: "xcm::process_instruction::transact", + "Call filtered by `SafeCallFilter`", + ); + + return Err(XcmError::NoPermission) + } + let dispatch_origin = Config::OriginConverter::convert_origin(origin, origin_kind) - .map_err(|_| XcmError::BadOrigin)?; + .map_err(|_| { + log::trace!( + target: "xcm::process_instruction::transact", + "Failed to convert origin {origin:?} and origin kind {origin_kind:?} to a local origin." + ); + + XcmError::BadOrigin + })?; + + log::trace!( + target: "xcm::process_instruction::transact", + "Dispatching with origin: {dispatch_origin:?}", + ); + let weight = message_call.get_dispatch_info().weight; - ensure!(weight.all_lte(require_weight_at_most), XcmError::MaxWeightInvalid); + + if !weight.all_lte(require_weight_at_most) { + log::trace!( + target: "xcm::process_instruction::transact", + "Max {weight} bigger than require at most {require_weight_at_most}", + ); + + return Err(XcmError::MaxWeightInvalid) + } + let maybe_actual_weight = match Config::CallDispatcher::dispatch(message_call, dispatch_origin) { Ok(post_info) => { + log::trace!( + target: "xcm::process_instruction::transact", + "Dispatch successful: {post_info:?}" + ); self.transact_status = MaybeErrorCode::Success; post_info.actual_weight }, Err(error_and_info) => { + log::trace!( + target: "xcm::process_instruction::transact", + "Dispatch failed {error_and_info:?}" + ); + self.transact_status = error_and_info.error.encode().into(); error_and_info.post_info.actual_weight }, @@ -946,93 +1088,4 @@ impl XcmExecutor { HrmpChannelClosing { .. } => Err(XcmError::Unimplemented), } } - - fn take_fee(&mut self, fee: MultiAssets, reason: FeeReason) -> XcmResult { - if Config::FeeManager::is_waived(self.origin_ref(), reason) { - return Ok(()) - } - log::trace!( - target: "xcm::fees", - "taking fee: {:?} from origin_ref: {:?} in fees_mode: {:?} for a reason: {:?}", - fee, - self.origin_ref(), - self.fees_mode, - reason, - ); - let paid = if self.fees_mode.jit_withdraw { - let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?; - for asset in fee.inner() { - Config::AssetTransactor::withdraw_asset(&asset, origin, Some(&self.context))?; - } - fee - } else { - self.holding.try_take(fee.into()).map_err(|_| XcmError::NotHoldingFees)?.into() - }; - Config::FeeManager::handle_fee(paid, Some(&self.context), reason); - Ok(()) - } - - /// Calculates what `local_querier` would be from the perspective of `destination`. - fn to_querier( - local_querier: Option, - destination: &MultiLocation, - ) -> Result, XcmError> { - Ok(match local_querier { - None => None, - Some(q) => Some( - q.reanchored(&destination, Config::UniversalLocation::get()) - .map_err(|_| XcmError::ReanchorFailed)?, - ), - }) - } - - /// Send a bare `QueryResponse` message containing `response` informed by the given `info`. - /// - /// The `local_querier` argument is the querier (if any) specified from the *local* perspective. - fn respond( - &mut self, - local_querier: Option, - response: Response, - info: QueryResponseInfo, - fee_reason: FeeReason, - ) -> Result { - let querier = Self::to_querier(local_querier, &info.destination)?; - let QueryResponseInfo { destination, query_id, max_weight } = info; - let instruction = QueryResponse { query_id, response, max_weight, querier }; - let message = Xcm(vec![instruction]); - self.send(destination, message, fee_reason) - } - - fn try_reanchor( - asset: MultiAsset, - destination: &MultiLocation, - ) -> Result<(MultiAsset, InteriorMultiLocation), XcmError> { - let reanchor_context = Config::UniversalLocation::get(); - let asset = asset - .reanchored(&destination, reanchor_context) - .map_err(|()| XcmError::ReanchorFailed)?; - Ok((asset, reanchor_context)) - } - - fn try_reanchor_multilocation( - location: MultiLocation, - destination: &MultiLocation, - ) -> Result<(MultiLocation, InteriorMultiLocation), XcmError> { - let reanchor_context = Config::UniversalLocation::get(); - let location = location - .reanchored(&destination, reanchor_context) - .map_err(|_| XcmError::ReanchorFailed)?; - Ok((location, reanchor_context)) - } - - /// NOTE: Any assets which were unable to be reanchored are introduced into `failed_bin`. - fn reanchored( - mut assets: Assets, - dest: &MultiLocation, - maybe_failed_bin: Option<&mut Assets>, - ) -> MultiAssets { - let reanchor_context = Config::UniversalLocation::get(); - assets.reanchor(dest, reanchor_context, maybe_failed_bin); - assets.into_assets_iter().collect::>().into() - } } diff --git a/prdoc/pr_2799.prdoc b/prdoc/pr_2799.prdoc new file mode 100644 index 0000000000..436dea643e --- /dev/null +++ b/prdoc/pr_2799.prdoc @@ -0,0 +1,10 @@ +title: Improve XCM debuggability + +doc: + - audience: Runtime User + description: | + Adds more logging to XCM execution to improve its debuggability. + +crates: + - name: "staging-xcm-builder" + - name: "staging-xcm-executor" diff --git a/substrate/primitives/runtime/src/traits.rs b/substrate/primitives/runtime/src/traits.rs index 2ac4047a80..ad82419cb8 100644 --- a/substrate/primitives/runtime/src/traits.rs +++ b/substrate/primitives/runtime/src/traits.rs @@ -1438,7 +1438,7 @@ pub trait Dispatchable { /// Every function call from your runtime has an origin, which specifies where the extrinsic was /// generated from. In the case of a signed extrinsic (transaction), the origin contains an /// identifier for the caller. The origin can be empty in the case of an inherent extrinsic. - type RuntimeOrigin; + type RuntimeOrigin: Debug; /// ... type Config; /// An opaque set of information attached to the transaction. This could be constructed anywhere