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

[xcm-emulator] Better logs for message execution and processing #5712

Merged
merged 5 commits into from
Sep 19, 2024
Merged

[xcm-emulator] Better logs for message execution and processing #5712

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
e8f1715
chore(xcm-emulator): better logs for message processing
franciscoaguirre Sep 13, 2024
c557c49
Merge branch 'master' into xcm-emulator-better-transport-logs
franciscoaguirre Sep 16, 2024
5ffe707
doc: add prdoc
franciscoaguirre Sep 16, 2024
968665c
chore(xcm-emulator): use array-bytes instead of hex
franciscoaguirre Sep 16, 2024
b3205c1
fix: fmt
franciscoaguirre Sep 16, 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
1 change: 1 addition & 0 deletions Cargo.lock
View file
Open in desktop

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

1 change: 1 addition & 0 deletions cumulus/xcm/xcm-emulator/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ paste = { workspace = true, default-features = true }
log = { workspace = true }
lazy_static = { workspace = true }
impl-trait-for-tuples = { workspace = true }
hex = { workspace = true }
franciscoaguirre marked this conversation as resolved.
Show resolved Hide resolved

# Substrate
frame-support = { workspace = true, default-features = true }
Expand Down
34 changes: 24 additions & 10 deletions cumulus/xcm/xcm-emulator/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
extern crate alloc;

pub use codec::{Decode, Encode, EncodeLike, MaxEncodedLen};
pub use hex;
pub use lazy_static::lazy_static;
pub use log;
pub use paste;
Expand Down Expand Up @@ -526,7 +527,10 @@ macro_rules! __impl_test_ext_for_relay_chain {
<$network>::init();

// Execute
let r = $local_ext.with(|v| v.borrow_mut().execute_with(execute));
let r = $local_ext.with(|v| {
$crate::log::info!(target: "xcm::emulator::execute_with", "Executing as {}", stringify!($name));
v.borrow_mut().execute_with(execute)
});

// Send messages if needed
$local_ext.with(|v| {
Expand All @@ -550,7 +554,7 @@ macro_rules! __impl_test_ext_for_relay_chain {

// log events
Self::events().iter().for_each(|event| {
$crate::log::debug!(target: concat!("events::", stringify!($name)), "{:?}", event);
$crate::log::info!(target: concat!("events::", stringify!($name)), "{:?}", event);
});

// clean events
Expand Down Expand Up @@ -826,7 +830,10 @@ macro_rules! __impl_test_ext_for_parachain {
Self::new_block();

// Execute
let r = $local_ext.with(|v| v.borrow_mut().execute_with(execute));
let r = $local_ext.with(|v| {
$crate::log::trace!(target: "xcm::emulator::execute_with", "Executing as {}", stringify!($name));
v.borrow_mut().execute_with(execute)
});

// Finalize the block
Self::finalize_block();
Expand Down Expand Up @@ -872,7 +879,7 @@ macro_rules! __impl_test_ext_for_parachain {

// log events
<Self as $crate::Chain>::events().iter().for_each(|event| {
$crate::log::debug!(target: concat!("events::", stringify!($name)), "{:?}", event);
$crate::log::info!(target: concat!("events::", stringify!($name)), "{:?}", event);
});

// clean events
Expand Down Expand Up @@ -1024,7 +1031,10 @@ macro_rules! decl_test_networks {
&mut msg.using_encoded($crate::blake2_256),
);
});
$crate::log::debug!(target: concat!("dmp::", stringify!($name)) , "DMP messages processed {:?} to para_id {:?}", msgs.clone(), &to_para_id);
let messages = msgs.clone().iter().map(|(block, message)| {
(*block, format!("0x{}", $crate::hex::encode(message)))
}).collect::<Vec<_>>();
$crate::log::info!(target: concat!("xcm::dmp::", stringify!($name)) , "Downward messages processed by para_id {:?}: {:?}", &to_para_id, messages);
$crate::DMP_DONE.with(|b| b.borrow_mut().get_mut(Self::name()).unwrap().push_back((to_para_id, block, msg)));
}
}
Expand All @@ -1037,7 +1047,7 @@ macro_rules! decl_test_networks {

while let Some((to_para_id, messages))
= $crate::HORIZONTAL_MESSAGES.with(|b| b.borrow_mut().get_mut(Self::name()).unwrap().pop_front()) {
let iter = messages.iter().map(|(p, b, m)| (*p, *b, &m[..])).collect::<Vec<_>>().into_iter();
let iter = messages.iter().map(|(para_id, relay_block_number, message)| (*para_id, *relay_block_number, &message[..])).collect::<Vec<_>>().into_iter();
$(
let para_id: u32 = <$parachain<Self>>::para_id().into();

Expand All @@ -1047,7 +1057,10 @@ macro_rules! decl_test_networks {
// Nudge the MQ pallet to process immediately instead of in the next block.
let _ = <$parachain<Self> as Parachain>::MessageProcessor::service_queues($crate::Weight::MAX);
});
$crate::log::debug!(target: concat!("hrmp::", stringify!($name)) , "HRMP messages processed {:?} to para_id {:?}", &messages, &to_para_id);
let messages = messages.clone().iter().map(|(para_id, relay_block_number, message)| {
(*para_id, *relay_block_number, format!("0x{}", $crate::hex::encode(message)))
}).collect::<Vec<_>>();
$crate::log::info!(target: concat!("xcm::hrmp::", stringify!($name)), "Horizontal messages processed by para_id {:?}: {:?}", &to_para_id, &messages);
}
)*
}
Expand All @@ -1066,7 +1079,8 @@ macro_rules! decl_test_networks {
&mut msg.using_encoded($crate::blake2_256),
);
});
$crate::log::debug!(target: concat!("ump::", stringify!($name)) , "Upward message processed {:?} from para_id {:?}", &msg, &from_para_id);
let message = format!("0x{}", $crate::hex::encode(msg.clone()));
$crate::log::info!(target: concat!("xcm::ump::", stringify!($name)) , "Upward message processed from para_id {:?}: {:?}", &from_para_id, &message);
}
}

Expand All @@ -1086,7 +1100,7 @@ macro_rules! decl_test_networks {
<<Self::Bridge as Bridge>::Source as TestExt>::ext_wrapper(|| {
<<Self::Bridge as Bridge>::Handler as BridgeMessageHandler>::notify_source_message_delivery(msg.lane_id.clone());
});
$crate::log::debug!(target: concat!("bridge::", stringify!($name)) , "Bridged message processed {:?}", msg);
$crate::log::info!(target: concat!("bridge::", stringify!($name)) , "Bridged message processed {:?}", msg);
}
}
}
Expand Down Expand Up @@ -1297,7 +1311,7 @@ macro_rules! assert_expected_events {
if !message.is_empty() {
// Log events as they will not be logged after the panic
<$chain as $crate::Chain>::events().iter().for_each(|event| {
$crate::log::debug!(target: concat!("events::", stringify!($chain)), "{:?}", event);
$crate::log::info!(target: concat!("events::", stringify!($chain)), "{:?}", event);
});
panic!("{}", message.concat())
}
Expand Down
Loading