Skip to content

Commit

Permalink
xcm-executor: Improve logging (#4996)
Browse files Browse the repository at this point in the history 
This improves logging in the xcm-executor to have better debugability
when executing a XCM message.
  • Loading branch information
@bkchr
bkchr authored Jul 12, 2024
1 parent 53598b8 commit 2a555c3
Show file tree
Hide file tree
Showing 9 changed files with 208 additions and 116 deletions.
2 changes: 1 addition & 1 deletion Cargo.lock
View file

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

4 changes: 2 additions & 2 deletions polkadot/xcm/xcm-executor/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand All @@ -37,13 +37,13 @@ std = [
"environmental/std",
"frame-benchmarking/std",
"frame-support/std",
"log/std",
"scale-info/std",
"sp-arithmetic/std",
"sp-core/std",
"sp-io/std",
"sp-runtime/std",
"sp-std/std",
"sp-weights/std",
"tracing/std",
"xcm/std",
]
148 changes: 89 additions & 59 deletions polkadot/xcm/xcm-executor/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -208,9 +208,12 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
weight_credit: Weight,
) -> 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 };

Expand All @@ -226,10 +229,13 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
xcm_weight,
&mut properties,
) {
log::trace!(
tracing::trace!(
target: "xcm::execute",
"Barrier blocked execution! Error: {e:?}. \
(origin: {origin:?}, message: {message:?}, properties: {properties:?})",
?origin,
?message,
?properties,
error = ?e,
"Barrier blocked execution",
);
return Outcome::Error { error: XcmError::Barrier }
}
Expand All @@ -240,7 +246,7 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con

while !message.0.is_empty() {
let result = vm.process(message);
log::trace!(target: "xcm::execute", "result: {result:?}");
tracing::trace!(target: "xcm::execute", ?result, "Message executed");
message = if let Err(error) = result {
vm.total_surplus.saturating_accrue(error.weight);
vm.error = Some((error.index, error.xcm_error));
Expand Down Expand Up @@ -282,11 +288,11 @@ pub struct ExecutorError {
#[cfg(feature = "runtime-benchmarks")]
impl From<ExecutorError> 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")
}
Expand Down Expand Up @@ -326,10 +332,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
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 =
Expand All @@ -342,7 +350,13 @@ impl<Config: config::Config> XcmExecutor<Config> {
// 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 }
},
}
Expand All @@ -363,8 +377,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
msg: Xcm<()>,
reason: FeeReason,
) -> Result<XcmHash, XcmError> {
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::<Config::XcmSender>(dest, msg)?;
self.take_fee(fee, reason)?;
Expand Down Expand Up @@ -400,20 +418,25 @@ impl<Config: config::Config> XcmExecutor<Config> {
// `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(())
}

/// 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) {
Expand All @@ -426,7 +449,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
.defensive_proof(
"refund_weight returned an asset capable of buying weight; qed",
);
log::error!(
tracing::error!(
target: "xcm::refund_surplus",
"error: HoldingWouldOverflow",
);
Expand All @@ -436,10 +459,9 @@ impl<Config: config::Config> XcmExecutor<Config> {
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(())
}
Expand All @@ -448,13 +470,13 @@ impl<Config: config::Config> XcmExecutor<Config> {
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)?;
Expand Down Expand Up @@ -507,7 +529,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
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))
Expand All @@ -530,13 +552,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
}

fn process(&mut self, xcm: Xcm<Config::RuntimeCall>) -> 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() {
Expand Down Expand Up @@ -566,7 +587,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
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,
Expand All @@ -588,11 +609,12 @@ impl<Config: config::Config> XcmExecutor<Config> {
&mut self,
instr: Instruction<Config::RuntimeCall>,
) -> 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)?;
Expand Down Expand Up @@ -694,7 +716,7 @@ impl<Config: config::Config> XcmExecutor<Config> {
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",
);
Expand All @@ -704,21 +726,22 @@ impl<Config: config::Config> XcmExecutor<Config> {

// 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",
);

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`",
);
Expand All @@ -729,26 +752,31 @@ impl<Config: config::Config> XcmExecutor<Config> {
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)
Expand All @@ -757,17 +785,19 @@ impl<Config: config::Config> XcmExecutor<Config> {
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();
Expand Down
Loading

0 comments on commit 2a555c3

Please sign in to comment.