diff --git a/Cargo.lock b/Cargo.lock index bbd39f1d7274..1c7bdafd4dbd 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -23632,6 +23632,7 @@ dependencies = [ name = "xcm-emulator" version = "0.15.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 3cee7810d341..915f9803ac58 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 } +<<<<<<< HEAD frame-support.workspace = true frame-support.default-features = true frame-system.workspace = true @@ -59,3 +60,34 @@ polkadot-parachain-primitives.workspace = true polkadot-parachain-primitives.default-features = true polkadot-runtime-parachains.workspace = true polkadot-runtime-parachains.default-features = true +======= +array-bytes = { workspace = true } + +# Substrate +frame-support = { workspace = true, default-features = true } +frame-system = { workspace = true, default-features = true } +sp-io = { workspace = true, default-features = true } +sp-core = { workspace = true, default-features = true } +sp-crypto-hashing = { workspace = true, default-features = true } +sp-std = { workspace = true, default-features = true } +sp-runtime = { workspace = true, default-features = true } +sp-arithmetic = { workspace = true, default-features = true } +sp-tracing = { workspace = true, default-features = true } +pallet-balances = { workspace = true, default-features = true } +pallet-message-queue = { workspace = true, default-features = true } + +# Cumulus +cumulus-primitives-core = { workspace = true, default-features = true } +cumulus-pallet-xcmp-queue = { workspace = true, default-features = true } +cumulus-pallet-parachain-system = { workspace = true, default-features = true } +cumulus-primitives-parachain-inherent = { workspace = true, default-features = true } +cumulus-test-relay-sproof-builder = { workspace = true, default-features = true } +parachains-common = { workspace = true, default-features = true } + +# Polkadot +xcm = { workspace = true, default-features = true } +xcm-executor = { workspace = true, default-features = true } +polkadot-primitives = { workspace = true, default-features = true } +polkadot-parachain-primitives = { workspace = true, default-features = true } +polkadot-runtime-parachains = { workspace = true, default-features = true } +>>>>>>> b230b0e ([xcm-emulator] Better logs for message execution and processing (#5712)) diff --git a/cumulus/xcm/xcm-emulator/src/lib.rs b/cumulus/xcm/xcm-emulator/src/lib.rs index 8de3660c2236..4caea554a6a5 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; @@ -524,7 +525,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| { @@ -548,7 +552,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 @@ -824,7 +828,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(); @@ -870,7 +877,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 @@ -1022,7 +1029,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))); } } @@ -1035,7 +1045,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(); @@ -1045,7 +1055,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); } )* } @@ -1064,7 +1077,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); } } @@ -1084,7 +1098,11 @@ macro_rules! decl_test_networks { <::Source as TestExt>::ext_wrapper(|| { <::Handler as BridgeMessageHandler>::notify_source_message_delivery(msg.id); }); +<<<<<<< HEAD $crate::log::debug!(target: concat!("bridge::", stringify!($name)) , "Bridged message processed {:?}", msg.clone()); +======= + $crate::log::info!(target: concat!("bridge::", stringify!($name)) , "Bridged message processed {:?}", msg); +>>>>>>> b230b0e ([xcm-emulator] Better logs for message execution and processing (#5712)) } } } @@ -1295,7 +1313,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