From b230b0e32b8a12ab9b53b6a1040ba26a55704947 Mon Sep 17 00:00:00 2001
From: Francisco Aguirre <franciscoaguirreperez@gmail.com>
Date: Thu, 19 Sep 2024 08:38:00 +0200
Subject: [PATCH] [xcm-emulator] Better logs for message execution and
processing (#5712)
When running XCM emulated tests and seeing the logs with `RUST_LOG=xcm`
or `RUST_LOG=xcm=trace`, it's sometimes a bit hard to figure out the
chain where the logs are coming from.
I added a log whenever `execute_with` is called, to know the chain which
makes the following logs. Looks like so:
<img width="1499" alt="Screenshot 2024-09-13 at 20 14 13"
src="https://github.com/user-attachments/assets/a31d7aa4-11d1-4d3e-9a65-86f38347c880">
There are already log targets for when UMP, DMP and HRMP messages are
being processed. To see them, you have to use the log targets `ump`,
`dmp`, and `hrmp` respectively. So `RUST_LOG=xcm,ump,dmp,hrmp` would let
you see every log.
I prefixed the targets with `xcm::` so you can get all the relevant logs
just by filtering by `xcm`. You can always use the whole target to see
just the messages being processed.
These logs showed the message as an array of bytes, I made them show a
hexadecimal string instead since that's easier to copy in case you want
to decode it or use it in another tool. They look like this now:
<img width="1499" alt="Screenshot 2024-09-13 at 20 17 15"
src="https://github.com/user-attachments/assets/5abf4a97-1ea7-4832-b3b0-d54c54905d1a">
The HRMP and UMP ones are very similar.
---
Cargo.lock | 1 +
cumulus/xcm/xcm-emulator/Cargo.toml | 1 +
cumulus/xcm/xcm-emulator/src/lib.rs | 34 ++++++++++++++++++++---------
prdoc/pr_5712.prdoc | 18 +++++++++++++++
4 files changed, 44 insertions(+), 10 deletions(-)
create mode 100644 prdoc/pr_5712.prdoc
diff --git a/Cargo.lock b/Cargo.lock
index 373e62c093a..2a8f570fabe 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -26959,6 +26959,7 @@ dependencies = [
name = "xcm-emulator"
version = "0.5.0"
dependencies = [
+ "array-bytes",
"cumulus-pallet-parachain-system",
"cumulus-pallet-xcmp-queue",
"cumulus-primitives-core",
diff --git a/cumulus/xcm/xcm-emulator/Cargo.toml b/cumulus/xcm/xcm-emulator/Cargo.toml
index ba1097fba07..6924f11292d 100644
--- a/cumulus/xcm/xcm-emulator/Cargo.toml
+++ b/cumulus/xcm/xcm-emulator/Cargo.toml
@@ -15,6 +15,7 @@ paste = { workspace = true, default-features = true }
log = { workspace = true }
lazy_static = { workspace = true }
impl-trait-for-tuples = { workspace = true }
+array-bytes = { workspace = true }
# Substrate
frame-support = { workspace = true, default-features = true }
diff --git a/cumulus/xcm/xcm-emulator/src/lib.rs b/cumulus/xcm/xcm-emulator/src/lib.rs
index 76bbad38d5e..d393d453773 100644
--- a/cumulus/xcm/xcm-emulator/src/lib.rs
+++ b/cumulus/xcm/xcm-emulator/src/lib.rs
@@ -16,6 +16,7 @@
extern crate alloc;
+pub use array_bytes;
pub use codec::{Decode, Encode, EncodeLike, MaxEncodedLen};
pub use lazy_static::lazy_static;
pub use log;
@@ -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| {
@@ -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
@@ -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::info!(target: "xcm::emulator::execute_with", "Executing as {}", stringify!($name));
+ v.borrow_mut().execute_with(execute)
+ });
// Finalize the block
Self::finalize_block();
@@ -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
@@ -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, $crate::array_bytes::bytes2hex("0x", 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)));
}
}
@@ -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();
@@ -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, $crate::array_bytes::bytes2hex("0x", message))
+ }).collect::<Vec<_>>();
+ $crate::log::info!(target: concat!("xcm::hrmp::", stringify!($name)), "Horizontal messages processed by para_id {:?}: {:?}", &to_para_id, &messages);
}
)*
}
@@ -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 = $crate::array_bytes::bytes2hex("0x", msg.clone());
+ $crate::log::info!(target: concat!("xcm::ump::", stringify!($name)) , "Upward message processed from para_id {:?}: {:?}", &from_para_id, &message);
}
}
@@ -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);
}
}
}
@@ -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())
}
diff --git a/prdoc/pr_5712.prdoc b/prdoc/pr_5712.prdoc
new file mode 100644
index 00000000000..321ed12f313
--- /dev/null
+++ b/prdoc/pr_5712.prdoc
@@ -0,0 +1,18 @@
+# Schema: Polkadot SDK PRDoc Schema (prdoc) v1.0.0
+# See doc at https://raw.githubusercontent.com/paritytech/polkadot-sdk/master/prdoc/schema_user.json
+
+title: Better logs for XCM emulator
+
+doc:
+ - audience: Runtime Dev
+ description: |
+ Now the XCM emulator has a log every time `execute_with` is called, to know
+ which chain is being used.
+ Also, the logs for UMP, DMP, HRMP processing were included in the `xcm` log filter
+ and changed from showing the message as an array of bytes to a hex string.
+ This means running the tests with `RUST_LOG=xcm` should give you everything you need,
+ you can always filter by `RUST_LOG=xcm::hrmp` or any other if you need it.
+
+crates:
+ - name: xcm-emulator
+ bump: patch
--
GitLab