From b230b0e32b8a12ab9b53b6a1040ba26a55704947 Mon Sep 17 00:00:00 2001 From: Francisco Aguirre 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: Screenshot 2024-09-13 at 20 14 13 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: Screenshot 2024-09-13 at 20 17 15 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 373e62c093a0..2a8f570fabe4 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 ba1097fba075..6924f11292d6 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 76bbad38d5e6..d393d4537734 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 ::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::>(); + $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::>().into_iter(); + let iter = messages.iter().map(|(para_id, relay_block_number, message)| (*para_id, *relay_block_number, &message[..])).collect::>().into_iter(); $( let para_id: u32 = <$parachain>::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 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::>(); + $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 { <::Source as TestExt>::ext_wrapper(|| { <::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 000000000000..321ed12f3135 --- /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