Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

xcm-executor: Improve logging #4996

Merged
merged 2 commits into from
Jul 12, 2024
Merged

xcm-executor: Improve logging #4996

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
a87b26a
xcm-executor: Improve logging
bkchr Jul 10, 2024
279ee51
Make FMT check happy
bkchr Jul 10, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion Cargo.lock
View file
Open in desktop

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
Open in desktop
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,7 +37,7 @@ std = [
"environmental/std",
"frame-benchmarking/std",
"frame-support/std",
"log/std",
"tracing/std",
"scale-info/std",
"sp-arithmetic/std",
"sp-core/std",
Expand Down
148 changes: 89 additions & 59 deletions polkadot/xcm/xcm-executor/src/lib.rs
View file
Open in desktop
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
Loading