From e8f1715ca28e4cfd1460633e867cb4fdf38c86b7 Mon Sep 17 00:00:00 2001 From: Francisco Aguirre Date: Fri, 13 Sep 2024 20:09:17 +0200 Subject: [PATCH 1/4] chore(xcm-emulator): better logs for message processing --- Cargo.lock | 1 + cumulus/xcm/xcm-emulator/Cargo.toml | 1 + cumulus/xcm/xcm-emulator/src/lib.rs | 34 ++++++++++++++++++++--------- 3 files changed, 26 insertions(+), 10 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5f0fa0f613f9..f89479a9e2b1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -24249,6 +24249,7 @@ dependencies = [ "cumulus-test-relay-sproof-builder", "frame-support", "frame-system", + "hex", "impl-trait-for-tuples", "lazy_static", "log", diff --git a/cumulus/xcm/xcm-emulator/Cargo.toml b/cumulus/xcm/xcm-emulator/Cargo.toml index ba1097fba075..2a7103e19ae7 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 } +hex = { 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 afed14278d17..f863e0ccdf41 100644 --- a/cumulus/xcm/xcm-emulator/src/lib.rs +++ b/cumulus/xcm/xcm-emulator/src/lib.rs @@ -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; @@ -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::trace!(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, format!("0x{}", $crate::hex::encode(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, format!("0x{}", $crate::hex::encode(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 = 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); } } @@ -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()) } From 5ffe707a2fa6d585c16f3b749a78628844dd3114 Mon Sep 17 00:00:00 2001 From: Francisco Aguirre Date: Mon, 16 Sep 2024 07:23:14 +0200 Subject: [PATCH 2/4] doc: add prdoc --- prdoc/pr_5712.prdoc | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) create mode 100644 prdoc/pr_5712.prdoc 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 From 968665c81cd0dda1d6314e636b9e2fc69eb47eea Mon Sep 17 00:00:00 2001 From: Francisco Aguirre Date: Mon, 16 Sep 2024 07:30:06 +0200 Subject: [PATCH 3/4] chore(xcm-emulator): use array-bytes instead of hex --- Cargo.lock | 2 +- cumulus/xcm/xcm-emulator/Cargo.toml | 2 +- cumulus/xcm/xcm-emulator/src/lib.rs | 10 +++++----- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 754a43dc7218..0ae6e4744150 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -24243,6 +24243,7 @@ dependencies = [ name = "xcm-emulator" version = "0.5.0" dependencies = [ + "array-bytes", "cumulus-pallet-parachain-system", "cumulus-pallet-xcmp-queue", "cumulus-primitives-core", @@ -24250,7 +24251,6 @@ dependencies = [ "cumulus-test-relay-sproof-builder", "frame-support", "frame-system", - "hex", "impl-trait-for-tuples", "lazy_static", "log", diff --git a/cumulus/xcm/xcm-emulator/Cargo.toml b/cumulus/xcm/xcm-emulator/Cargo.toml index 2a7103e19ae7..6924f11292d6 100644 --- a/cumulus/xcm/xcm-emulator/Cargo.toml +++ b/cumulus/xcm/xcm-emulator/Cargo.toml @@ -15,7 +15,7 @@ paste = { workspace = true, default-features = true } log = { workspace = true } lazy_static = { workspace = true } impl-trait-for-tuples = { workspace = true } -hex = { 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 f863e0ccdf41..48781b643cfb 100644 --- a/cumulus/xcm/xcm-emulator/src/lib.rs +++ b/cumulus/xcm/xcm-emulator/src/lib.rs @@ -17,7 +17,7 @@ extern crate alloc; pub use codec::{Decode, Encode, EncodeLike, MaxEncodedLen}; -pub use hex; +pub use array_bytes; pub use lazy_static::lazy_static; pub use log; pub use paste; @@ -831,7 +831,7 @@ macro_rules! __impl_test_ext_for_parachain { // Execute let r = $local_ext.with(|v| { - $crate::log::trace!(target: "xcm::emulator::execute_with", "Executing as {}", stringify!($name)); + $crate::log::info!(target: "xcm::emulator::execute_with", "Executing as {}", stringify!($name)); v.borrow_mut().execute_with(execute) }); @@ -1032,7 +1032,7 @@ macro_rules! decl_test_networks { ); }); let messages = msgs.clone().iter().map(|(block, message)| { - (*block, format!("0x{}", $crate::hex::encode(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))); @@ -1058,7 +1058,7 @@ macro_rules! decl_test_networks { let _ = <$parachain as Parachain>::MessageProcessor::service_queues($crate::Weight::MAX); }); let messages = messages.clone().iter().map(|(para_id, relay_block_number, message)| { - (*para_id, *relay_block_number, format!("0x{}", $crate::hex::encode(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); } @@ -1079,7 +1079,7 @@ macro_rules! decl_test_networks { &mut msg.using_encoded($crate::blake2_256), ); }); - let message = format!("0x{}", $crate::hex::encode(msg.clone())); + 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); } } From b3205c1b268e854f64497fb03af1fdf4e3276260 Mon Sep 17 00:00:00 2001 From: Francisco Aguirre Date: Mon, 16 Sep 2024 07:36:12 +0200 Subject: [PATCH 4/4] fix: fmt --- cumulus/xcm/xcm-emulator/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cumulus/xcm/xcm-emulator/src/lib.rs b/cumulus/xcm/xcm-emulator/src/lib.rs index 48781b643cfb..6580cbe9c886 100644 --- a/cumulus/xcm/xcm-emulator/src/lib.rs +++ b/cumulus/xcm/xcm-emulator/src/lib.rs @@ -16,8 +16,8 @@ extern crate alloc; -pub use codec::{Decode, Encode, EncodeLike, MaxEncodedLen}; pub use array_bytes; +pub use codec::{Decode, Encode, EncodeLike, MaxEncodedLen}; pub use lazy_static::lazy_static; pub use log; pub use paste;