[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.

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 }

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())
 		}

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