diff --git a/Cargo.lock b/Cargo.lock index 4cf34e97276f4..a6c0ba89b5167 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -21103,7 +21103,6 @@ dependencies = [ "frame-benchmarking", "frame-support", "impl-trait-for-tuples", - "log", "parity-scale-codec", "scale-info", "sp-arithmetic", @@ -21113,6 +21112,7 @@ dependencies = [ "sp-std 14.0.0", "sp-weights", "staging-xcm", + "tracing", ] [[package]] diff --git a/polkadot/xcm/xcm-executor/Cargo.toml b/polkadot/xcm/xcm-executor/Cargo.toml index 8f7b94612b597..7d1fc48692f9a 100644 --- a/polkadot/xcm/xcm-executor/Cargo.toml +++ b/polkadot/xcm/xcm-executor/Cargo.toml @@ -22,7 +22,7 @@ sp-core = { workspace = true } sp-runtime = { workspace = true } sp-weights = { workspace = true } frame-support = { workspace = true } -log = { workspace = true } +tracing = { workspace = true } frame-benchmarking = { optional = true, workspace = true } [features] @@ -37,7 +37,6 @@ std = [ "environmental/std", "frame-benchmarking/std", "frame-support/std", - "log/std", "scale-info/std", "sp-arithmetic/std", "sp-core/std", @@ -45,5 +44,6 @@ std = [ "sp-runtime/std", "sp-std/std", "sp-weights/std", + "tracing/std", "xcm/std", ] diff --git a/polkadot/xcm/xcm-executor/src/lib.rs b/polkadot/xcm/xcm-executor/src/lib.rs index da9de93ca0f6f..aeeb24dcf8124 100644 --- a/polkadot/xcm/xcm-executor/src/lib.rs +++ b/polkadot/xcm/xcm-executor/src/lib.rs @@ -208,9 +208,12 @@ impl ExecuteXcm for XcmExecutor Outcome { let origin = origin.into(); - log::trace!( + tracing::trace!( target: "xcm::execute", - "origin: {origin:?}, message: {message:?}, weight_credit: {weight_credit:?}", + ?origin, + ?message, + ?weight_credit, + "Executing message", ); let mut properties = Properties { weight_credit, message_id: None }; @@ -226,10 +229,13 @@ impl ExecuteXcm for XcmExecutor ExecuteXcm for XcmExecutor for frame_benchmarking::BenchmarkError { fn from(error: ExecutorError) -> Self { - log::error!( - "XCM ERROR >> Index: {:?}, Error: {:?}, Weight: {:?}", - error.index, - error.xcm_error, - error.weight + tracing::error!( + index = ?error.index, + xcm_error = ?error.xcm_error, + weight = ?error.weight, + "XCM ERROR", ); Self::Stop("xcm executor error: see error logs") } @@ -326,10 +332,12 @@ impl XcmExecutor { let mut weight_used = xcm_weight.saturating_sub(self.total_surplus); if !self.holding.is_empty() { - log::trace!( + tracing::trace!( target: "xcm::post_process", - "Trapping assets in holding register: {:?}, context: {:?} (original_origin: {:?})", - self.holding, self.context, self.original_origin, + holding_register = ?self.holding, + context = ?self.context, + original_origin = ?self.original_origin, + "Trapping assets in holding register", ); let effective_origin = self.context.origin.as_ref().unwrap_or(&self.original_origin); let trap_weight = @@ -342,7 +350,13 @@ impl XcmExecutor { // TODO: #2841 #REALWEIGHT We should deduct the cost of any instructions following // the error which didn't end up being executed. Some((_i, e)) => { - log::trace!(target: "xcm::post_process", "Execution errored at {:?}: {:?} (original_origin: {:?})", _i, e, self.original_origin); + tracing::trace!( + target: "xcm::post_process", + instruction = ?_i, + error = ?e, + original_origin = ?self.original_origin, + "Execution failed", + ); Outcome::Incomplete { used: weight_used, error: e } }, } @@ -363,8 +377,12 @@ impl XcmExecutor { msg: Xcm<()>, reason: FeeReason, ) -> Result { - log::trace!( - target: "xcm::send", "Sending msg: {msg:?}, to destination: {dest:?}, (reason: {reason:?})" + tracing::trace!( + target: "xcm::send", + ?msg, + destination = ?dest, + reason = ?reason, + "Sending msg", ); let (ticket, fee) = validate_send::(dest, msg)?; self.take_fee(fee, reason)?; @@ -400,7 +418,12 @@ impl XcmExecutor { // `holding_limit` items (which has a best case outcome of holding.len() == holding_limit), // then the operation is guaranteed to succeed. let worst_case_holding_len = self.holding.len() + assets_length; - log::trace!(target: "xcm::ensure_can_subsume_assets", "worst_case_holding_len: {:?}, holding_limit: {:?}", worst_case_holding_len, self.holding_limit); + tracing::trace!( + target: "xcm::ensure_can_subsume_assets", + ?worst_case_holding_len, + holding_limit = ?self.holding_limit, + "Ensuring subsume assets work", + ); ensure!(worst_case_holding_len <= self.holding_limit * 2, XcmError::HoldingWouldOverflow); Ok(()) } @@ -408,12 +431,12 @@ impl XcmExecutor { /// Refund any unused weight. fn refund_surplus(&mut self) -> Result<(), XcmError> { let current_surplus = self.total_surplus.saturating_sub(self.total_refunded); - log::trace!( + tracing::trace!( target: "xcm::refund_surplus", - "total_surplus: {:?}, total_refunded: {:?}, current_surplus: {:?}", - self.total_surplus, - self.total_refunded, - current_surplus, + total_surplus = ?self.total_surplus, + total_refunded = ?self.total_refunded, + ?current_surplus, + "Refunding surplus", ); if current_surplus.any_gt(Weight::zero()) { if let Some(w) = self.trader.refund_weight(current_surplus, &self.context) { @@ -426,7 +449,7 @@ impl XcmExecutor { .defensive_proof( "refund_weight returned an asset capable of buying weight; qed", ); - log::error!( + tracing::error!( target: "xcm::refund_surplus", "error: HoldingWouldOverflow", ); @@ -436,10 +459,9 @@ impl XcmExecutor { self.holding.subsume_assets(w.into()); } } - log::trace!( + tracing::trace!( target: "xcm::refund_surplus", - "total_refunded: {:?}", - self.total_refunded, + total_refunded = ?self.total_refunded, ); Ok(()) } @@ -448,13 +470,13 @@ impl XcmExecutor { if Config::FeeManager::is_waived(self.origin_ref(), reason.clone()) { return Ok(()) } - log::trace!( + tracing::trace!( target: "xcm::fees", - "taking fee: {:?} from origin_ref: {:?} in fees_mode: {:?} for a reason: {:?}", - fee, - self.origin_ref(), - self.fees_mode, - reason, + ?fee, + origin_ref = ?self.origin_ref(), + fees_mode = ?self.fees_mode, + ?reason, + "Taking fees", ); let paid = if self.fees_mode.jit_withdraw { let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?; @@ -507,7 +529,7 @@ impl XcmExecutor { let reanchor_context = Config::UniversalLocation::get(); let reanchored = reanchorable.reanchored(&destination, &reanchor_context).map_err(|error| { - log::error!(target: "xcm::reanchor", "Failed reanchoring with error {error:?}"); + tracing::error!(target: "xcm::reanchor", ?error, "Failed reanchoring with error"); XcmError::ReanchorFailed })?; Ok((reanchored, reanchor_context)) @@ -530,13 +552,12 @@ impl XcmExecutor { } fn process(&mut self, xcm: Xcm) -> Result<(), ExecutorError> { - log::trace!( + tracing::trace!( target: "xcm::process", - "origin: {:?}, total_surplus/refunded: {:?}/{:?}, error_handler_weight: {:?}", - self.origin_ref(), - self.total_surplus, - self.total_refunded, - self.error_handler_weight, + origin = ?self.origin_ref(), + total_surplus = ?self.total_surplus, + total_refunded = ?self.total_refunded, + error_handler_weight = ?self.error_handler_weight, ); let mut result = Ok(()); for (i, instr) in xcm.0.into_iter().enumerate() { @@ -566,7 +587,7 @@ impl XcmExecutor { self.process_instruction(instr) }); if let Err(e) = inst_res { - log::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e); + tracing::trace!(target: "xcm::execute", "!!! ERROR: {:?}", e); *r = Err(ExecutorError { index: i as u32, xcm_error: e, @@ -588,11 +609,12 @@ impl XcmExecutor { &mut self, instr: Instruction, ) -> Result<(), XcmError> { - log::trace!( + tracing::trace!( target: "xcm::process_instruction", - "=== {:?}", - instr + instruction = ?instr, + "Processing instruction", ); + match instr { WithdrawAsset(assets) => { let origin = self.origin_ref().ok_or(XcmError::BadOrigin)?; @@ -694,7 +716,7 @@ 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.cloned_origin().ok_or_else(|| { - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", "No origin provided", ); @@ -704,7 +726,7 @@ impl XcmExecutor { // TODO: #2841 #TRANSACTFILTER allow the trait to issue filters for the relay-chain let message_call = call.take_decoded().map_err(|_| { - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", "Failed to decode call", ); @@ -712,13 +734,14 @@ impl XcmExecutor { XcmError::FailedToDecode })?; - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", - "Processing call: {message_call:?}", + ?call, + "Processing call", ); if !Config::SafeCallFilter::contains(&message_call) { - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", "Call filtered by `SafeCallFilter`", ); @@ -729,26 +752,31 @@ impl XcmExecutor { let dispatch_origin = Config::OriginConverter::convert_origin(origin.clone(), origin_kind).map_err( |_| { - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", - "Failed to convert origin {origin:?} and origin kind {origin_kind:?} to a local origin." + ?origin, + ?origin_kind, + "Failed to convert origin to a local origin." ); XcmError::BadOrigin }, )?; - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", - "Dispatching with origin: {dispatch_origin:?}", + origin = ?dispatch_origin, + "Dispatching with origin", ); let weight = message_call.get_dispatch_info().weight; if !weight.all_lte(require_weight_at_most) { - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", - "Max {weight} bigger than require at most {require_weight_at_most}", + %weight, + %require_weight_at_most, + "Max weight bigger than require at most", ); return Err(XcmError::MaxWeightInvalid) @@ -757,17 +785,19 @@ impl XcmExecutor { let maybe_actual_weight = match Config::CallDispatcher::dispatch(message_call, dispatch_origin) { Ok(post_info) => { - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", - "Dispatch successful: {post_info:?}" + ?post_info, + "Dispatch successful" ); self.transact_status = MaybeErrorCode::Success; post_info.actual_weight }, Err(error_and_info) => { - log::trace!( + tracing::trace!( target: "xcm::process_instruction::transact", - "Dispatch failed {error_and_info:?}" + ?error_and_info, + "Dispatch failed" ); self.transact_status = error_and_info.error.encode().into(); diff --git a/polkadot/xcm/xcm-executor/src/traits/conversion.rs b/polkadot/xcm/xcm-executor/src/traits/conversion.rs index 9e2f4c83997ac..1efe138b8c211 100644 --- a/polkadot/xcm/xcm-executor/src/traits/conversion.rs +++ b/polkadot/xcm/xcm-executor/src/traits/conversion.rs @@ -88,19 +88,45 @@ pub trait ConvertOrigin { #[impl_trait_for_tuples::impl_for_tuples(30)] impl ConvertOrigin for Tuple { fn convert_origin(origin: impl Into, kind: OriginKind) -> Result { + let origin = origin.into(); + + tracing::trace!( + target: "xcm::convert_origin", + ?origin, + ?kind, + "Converting origin", + ); + for_tuples!( #( + let convert_origin = core::any::type_name::(); + let origin = match Tuple::convert_origin(origin, kind) { - Err(o) => o, - r => return r + Err(o) => { + tracing::trace!( + target: "xcm::convert_origin", + %convert_origin, + "Convert origin step failed", + ); + + o + }, + Ok(o) => { + tracing::trace!( + target: "xcm::convert_origin", + %convert_origin, + "Convert origin step succeeded", + ); + + return Ok(o) + } }; )* ); - let origin = origin.into(); - log::trace!( + + tracing::trace!( target: "xcm::convert_origin", - "could not convert: origin: {:?}, kind: {:?}", - origin, - kind, + "Converting origin failed", ); + Err(origin) } } diff --git a/polkadot/xcm/xcm-executor/src/traits/should_execute.rs b/polkadot/xcm/xcm-executor/src/traits/should_execute.rs index e76d56bfe6164..2e3acf5960ec1 100644 --- a/polkadot/xcm/xcm-executor/src/traits/should_execute.rs +++ b/polkadot/xcm/xcm-executor/src/traits/should_execute.rs @@ -59,19 +59,35 @@ impl ShouldExecute for Tuple { properties: &mut Properties, ) -> Result<(), ProcessMessageError> { for_tuples!( #( - match Tuple::should_execute(origin, instructions, max_weight, properties) { - Ok(()) => return Ok(()), - _ => (), + let barrier = core::any::type_name::(); + match Tuple::should_execute(origin, instructions, max_weight, properties) { + Ok(()) => { + tracing::trace!( + target: "xcm::should_execute", + ?origin, + ?instructions, + ?max_weight, + ?properties, + %barrier, + "pass barrier", + ); + return Ok(()) + }, + Err(error) => { + tracing::trace!( + target: "xcm::should_execute", + ?origin, + ?instructions, + ?max_weight, + ?properties, + ?error, + %barrier, + "did not pass barrier", + ); + }, } )* ); - log::trace!( - target: "xcm::should_execute", - "did not pass barrier: origin: {:?}, instructions: {:?}, max_weight: {:?}, properties: {:?}", - origin, - instructions, - max_weight, - properties, - ); + Err(ProcessMessageError::Unsupported) } } diff --git a/polkadot/xcm/xcm-executor/src/traits/token_matching.rs b/polkadot/xcm/xcm-executor/src/traits/token_matching.rs index e9a7e3ad845da..45f3dc062a6d0 100644 --- a/polkadot/xcm/xcm-executor/src/traits/token_matching.rs +++ b/polkadot/xcm/xcm-executor/src/traits/token_matching.rs @@ -27,7 +27,7 @@ impl MatchesFungible for Tuple { for_tuples!( #( match Tuple::matches_fungible(a) { o @ Some(_) => return o, _ => () } )* ); - log::trace!(target: "xcm::matches_fungible", "did not match fungible asset: {:?}", &a); + tracing::trace!(target: "xcm::matches_fungible", asset = ?a, "did not match fungible asset"); None } } @@ -42,7 +42,7 @@ impl MatchesNonFungible for Tuple { for_tuples!( #( match Tuple::matches_nonfungible(a) { o @ Some(_) => return o, _ => () } )* ); - log::trace!(target: "xcm::matches_non_fungible", "did not match non-fungible asset: {:?}", &a); + tracing::trace!(target: "xcm::matches_non_fungible", asset = ?a, "did not match non-fungible asset"); None } } @@ -86,7 +86,7 @@ impl MatchesFungibles for Tuple { for_tuples!( #( match Tuple::matches_fungibles(a) { o @ Ok(_) => return o, _ => () } )* ); - log::trace!(target: "xcm::matches_fungibles", "did not match fungibles asset: {:?}", &a); + tracing::trace!(target: "xcm::matches_fungibles", asset = ?a, "did not match fungibles asset"); Err(Error::AssetNotHandled) } } @@ -101,7 +101,7 @@ impl MatchesNonFungibles for Tuple { for_tuples!( #( match Tuple::matches_nonfungibles(a) { o @ Ok(_) => return o, _ => () } )* ); - log::trace!(target: "xcm::matches_non_fungibles", "did not match fungibles asset: {:?}", &a); + tracing::trace!(target: "xcm::matches_non_fungibles", asset = ?a, "did not match fungibles asset"); Err(Error::AssetNotHandled) } } diff --git a/polkadot/xcm/xcm-executor/src/traits/transact_asset.rs b/polkadot/xcm/xcm-executor/src/traits/transact_asset.rs index e8a52d8256851..eb85af0b80f30 100644 --- a/polkadot/xcm/xcm-executor/src/traits/transact_asset.rs +++ b/polkadot/xcm/xcm-executor/src/traits/transact_asset.rs @@ -148,12 +148,12 @@ impl TransactAsset for Tuple { r => return r, } )* ); - log::trace!( + tracing::trace!( target: "xcm::TransactAsset::can_check_in", - "asset not found: what: {:?}, origin: {:?}, context: {:?}", - what, - origin, - context, + ?what, + ?origin, + ?context, + "asset not found", ); Err(XcmError::AssetNotFound) } @@ -171,12 +171,12 @@ impl TransactAsset for Tuple { r => return r, } )* ); - log::trace!( + tracing::trace!( target: "xcm::TransactAsset::can_check_out", - "asset not found: what: {:?}, dest: {:?}, context: {:?}", - what, - dest, - context, + ?what, + ?dest, + ?context, + "asset not found", ); Err(XcmError::AssetNotFound) } @@ -194,12 +194,12 @@ impl TransactAsset for Tuple { r => return r, } )* ); - log::trace!( + tracing::trace!( target: "xcm::TransactAsset::deposit_asset", - "did not deposit asset: what: {:?}, who: {:?}, context: {:?}", - what, - who, - context, + ?what, + ?who, + ?context, + "did not deposit asset", ); Err(XcmError::AssetNotFound) } @@ -215,12 +215,12 @@ impl TransactAsset for Tuple { r => return r, } )* ); - log::trace!( + tracing::trace!( target: "xcm::TransactAsset::withdraw_asset", - "did not withdraw asset: what: {:?}, who: {:?}, maybe_context: {:?}", - what, - who, - maybe_context, + ?what, + ?who, + ?maybe_context, + "did not withdraw asset", ); Err(XcmError::AssetNotFound) } @@ -237,13 +237,13 @@ impl TransactAsset for Tuple { r => return r, } )* ); - log::trace!( + tracing::trace!( target: "xcm::TransactAsset::internal_transfer_asset", - "did not transfer asset: what: {:?}, from: {:?}, to: {:?}, context: {:?}", - what, - from, - to, - context, + ?what, + ?from, + ?to, + ?context, + "did not transfer asset", ); Err(XcmError::AssetNotFound) } diff --git a/polkadot/xcm/xcm-executor/src/traits/weight.rs b/polkadot/xcm/xcm-executor/src/traits/weight.rs index efb9a2dfb6efd..985dfcd0cf2d7 100644 --- a/polkadot/xcm/xcm-executor/src/traits/weight.rs +++ b/polkadot/xcm/xcm-executor/src/traits/weight.rs @@ -80,18 +80,38 @@ impl WeightTrader for Tuple { let mut too_expensive_error_found = false; let mut last_error = None; for_tuples!( #( + let weight_trader = core::any::type_name::(); + match Tuple.buy_weight(weight, payment.clone(), context) { - Ok(assets) => return Ok(assets), - Err(e) => { - if let XcmError::TooExpensive = e { + Ok(assets) => { + tracing::trace!( + target: "xcm::buy_weight", + %weight_trader, + "Buy weight succeeded", + ); + + return Ok(assets) + }, + Err(error) => { + if let XcmError::TooExpensive = error { too_expensive_error_found = true; } - last_error = Some(e) + last_error = Some(error); + + tracing::trace!( + target: "xcm::buy_weight", + ?error, + %weight_trader, + "Weight trader failed", + ); } } )* ); - log::trace!(target: "xcm::buy_weight", "last_error: {:?}, too_expensive_error_found: {}", last_error, too_expensive_error_found); + tracing::trace!( + target: "xcm::buy_weight", + "Buy weight failed", + ); // if we have multiple traders, and first one returns `TooExpensive` and others fail e.g. // `AssetNotFound` then it is more accurate to return `TooExpensive` then `AssetNotFound` diff --git a/substrate/frame/support/src/traits/messages.rs b/substrate/frame/support/src/traits/messages.rs index 2eec606b6d18b..3f8d80f5c6baf 100644 --- a/substrate/frame/support/src/traits/messages.rs +++ b/substrate/frame/support/src/traits/messages.rs @@ -27,7 +27,7 @@ use sp_weights::{Weight, WeightMeter}; /// Errors that can happen when attempting to process a message with /// [`ProcessMessage::process_message()`]. -#[derive(Copy, Clone, Eq, PartialEq, Encode, Decode, TypeInfo, RuntimeDebug)] +#[derive(Copy, Clone, Eq, PartialEq, Encode, Decode, TypeInfo, Debug)] pub enum ProcessMessageError { /// The message data format is unknown (e.g. unrecognised header) BadFormat,