Enhance XCM Debugging with Log Capture in Unit Tests (#7594)

# Description

This PR introduces a lightweight log-capturing mechanism for XCM unit
tests, simplifying debugging by enabling structured log assertions. It
partially addresses #6119 and #6125, offering an optional way to verify
logs in tests while remaining unobtrusive in normal execution.

# Key Changes

* [x] Introduces a log capture utility in `sp_tracing`.
* [x] Adds XCM test examples demonstrating how and when to use log
capturing.

# Review Notes:

* The log capture mechanism is opt-in and does not affect existing tests
unless explicitly used.
* The implementation is minimal and does not add complexity to existing
test setups.
* It provides a structured alternative to
[`sp_tracing::init_for_tests()`](https://paritytech.github.io/polkadot-sdk/master/sp_tracing/fn.init_for_tests.html)
for log verification in automated tests.

---------

Co-authored-by: cmd[bot] <41898282+github-actions[bot]@users.noreply.github.com>

Author: raymondkfcheung

polkadot/xcm/xcm-simulator/example/Cargo.toml

@@ -52,3 +52,6 @@ runtime-benchmarks = [
 	"xcm-executor/runtime-benchmarks",
 	"xcm/runtime-benchmarks",
 ]
+
+[dev-dependencies]
+sp-tracing = { features = ["test-utils"], workspace = true }

polkadot/xcm/xcm-simulator/example/src/tests.rs

@@ -136,6 +136,19 @@ fn reserve_transfer() {
 			relay_chain::Balances::free_balance(&child_account_id(1)),
 			INITIAL_BALANCE + withdraw_amount
 		);
+		// Ensure expected events were emitted
+		let events = relay_chain::System::events();
+		let attempted_count = count_relay_chain_events(&events, |event| {
+			matches!(
+				event,
+				relay_chain::RuntimeEvent::XcmPallet(pallet_xcm::Event::Attempted { .. })
+			)
+		});
+		let sent_count = count_relay_chain_events(&events, |event| {
+			matches!(event, relay_chain::RuntimeEvent::XcmPallet(pallet_xcm::Event::Sent { .. }))
+		});
+		assert_eq!(attempted_count, 1, "Expected one XcmPallet::Attempted event");
+		assert_eq!(sent_count, 1, "Expected one XcmPallet::Sent event");
 	});
 
 	ParaA::execute_with(|| {
@@ -147,6 +160,62 @@ fn reserve_transfer() {
 	});
 }
 
+#[test]
+fn reserve_transfer_with_error() {
+	use sp_tracing::{
+		test_log_capture::init_log_capture,
+		tracing::{subscriber, Level},
+	};
+
+	// Reset the test network
+	MockNet::reset();
+
+	// Execute XCM Transfer and Capture Logs
+	let (log_capture, subscriber) = init_log_capture(Level::ERROR);
+	subscriber::with_default(subscriber, || {
+		let invalid_dest = Box::new(Parachain(9999).into());
+		let withdraw_amount = 123;
+
+		Relay::execute_with(|| {
+			let result = RelayChainPalletXcm::limited_reserve_transfer_assets(
+				relay_chain::RuntimeOrigin::signed(ALICE),
+				invalid_dest,
+				Box::new(AccountId32 { network: None, id: ALICE.into() }.into()),
+				Box::new((Here, withdraw_amount).into()),
+				0,
+				Unlimited,
+			);
+
+			// Ensure an error occurred
+			assert!(result.is_err(), "Expected an error due to invalid destination");
+
+			// Assert captured logs
+			assert!(log_capture.contains("XCM validate_send failed"));
+
+			// Verify that XcmPallet::Attempted was NOT emitted (rollback happened)
+			let events = relay_chain::System::events();
+			let xcm_attempted_emitted = events.iter().any(|e| {
+				matches!(
+					e.event,
+					relay_chain::RuntimeEvent::XcmPallet(pallet_xcm::Event::Attempted { .. })
+				)
+			});
+			assert!(
+				!xcm_attempted_emitted,
+				"Expected no XcmPallet::Attempted event due to rollback, but it was emitted"
+			);
+		});
+
+		// Ensure no balance change due to the error
+		ParaA::execute_with(|| {
+			assert_eq!(
+				pallet_balances::Pallet::<parachain::Runtime>::free_balance(&ALICE),
+				INITIAL_BALANCE
+			);
+		});
+	});
+}
+
 #[test]
 fn remote_locking_and_unlocking() {
 	MockNet::reset();
@@ -511,3 +580,13 @@ fn query_holding() {
 		);
 	});
 }
+
+fn count_relay_chain_events<F>(
+	events: &[frame_system::EventRecord<relay_chain::RuntimeEvent, sp_core::H256>],
+	predicate: F,
+) -> usize
+where
+	F: Fn(&relay_chain::RuntimeEvent) -> bool,
+{
+	events.iter().filter(|e| predicate(&e.event)).count()
+}

prdoc/pr_7594.prdoc

@@ -0,0 +1,12 @@
+title: Improve XCM Debugging by Capturing Logs in Unit Tests
+doc:
+- audience: Runtime Dev
+  description: |-
+    This PR introduces a lightweight log-capturing mechanism for XCM unit tests, making it easier to troubleshoot failures when needed.
+crates:
+- name: pallet-xcm
+  bump: patch
+- name: xcm-simulator-example
+  bump: patch
+- name: sp-tracing
+  bump: minor

substrate/primitives/tracing/Cargo.toml

@@ -40,3 +40,4 @@ std = [
 	"tracing/std",
 	"with-tracing",
 ]
+test-utils = ["std"]

substrate/primitives/tracing/src/lib.rs

@@ -255,3 +255,189 @@ macro_rules! enter_span {
 		$crate::enter_span!($crate::span!($lvl, $name))
 	};
 }
+
+#[cfg(feature = "test-utils")]
+pub mod test_log_capture {
+	use std::{
+		io::Write,
+		sync::{Arc, Mutex},
+	};
+	use tracing::level_filters::LevelFilter;
+	use tracing_subscriber::fmt::{
+		format::{DefaultFields, Format},
+		MakeWriter, Subscriber,
+	};
+
+	/// A reusable log capturing struct for unit tests.
+	/// Captures logs written during test execution for assertions.
+	///
+	/// # Examples
+	/// ```
+	/// use sp_tracing::test_log_capture::LogCapture;
+	/// use std::io::Write;
+	///
+	/// let mut log_capture = LogCapture::new();
+	/// writeln!(log_capture, "Test log message").unwrap();
+	/// assert!(log_capture.contains("Test log message"));
+	/// ```
+	pub struct LogCapture {
+		buffer: Arc<Mutex<Vec<u8>>>,
+	}
+
+	impl LogCapture {
+		/// Creates a new `LogCapture` instance with an internal buffer.
+		///
+		/// # Examples
+		/// ```
+		/// use sp_tracing::test_log_capture::LogCapture;
+		///
+		/// let log_capture = LogCapture::new();
+		/// assert!(log_capture.get_logs().is_empty());
+		/// ```
+		pub fn new() -> Self {
+			LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) }
+		}
+
+		/// Checks if the captured logs contain a specific substring.
+		///
+		/// # Examples
+		/// ```
+		/// use sp_tracing::test_log_capture::LogCapture;
+		/// use std::io::Write;
+		///
+		/// let mut log_capture = LogCapture::new();
+		/// writeln!(log_capture, "Hello, world!").unwrap();
+		/// assert!(log_capture.contains("Hello"));
+		/// assert!(!log_capture.contains("Goodbye"));
+		/// ```
+		pub fn contains(&self, expected: &str) -> bool {
+			let logs = self.get_logs();
+			logs.contains(expected)
+		}
+
+		/// Retrieves the captured logs as a `String`.
+		///
+		/// # Examples
+		/// ```
+		/// use sp_tracing::test_log_capture::LogCapture;
+		/// use std::io::Write;
+		///
+		/// let mut log_capture = LogCapture::new();
+		/// writeln!(log_capture, "Log entry").unwrap();
+		/// assert_eq!(log_capture.get_logs().trim(), "Log entry");
+		/// ```
+		pub fn get_logs(&self) -> String {
+			String::from_utf8(self.buffer.lock().unwrap().clone()).unwrap()
+		}
+
+		/// Returns a clone of the internal buffer for use in `MakeWriter`.
+		pub fn writer(&self) -> Self {
+			LogCapture { buffer: Arc::clone(&self.buffer) }
+		}
+	}
+
+	impl Write for LogCapture {
+		/// Writes log data into the internal buffer.
+		fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
+			let mut logs = self.buffer.lock().unwrap();
+			logs.extend_from_slice(buf);
+			Ok(buf.len())
+		}
+
+		/// Flushes the internal buffer (no-op in this implementation).
+		fn flush(&mut self) -> std::io::Result<()> {
+			Ok(())
+		}
+	}
+
+	impl<'a> MakeWriter<'a> for LogCapture {
+		type Writer = Self;
+
+		/// Provides a `MakeWriter` implementation for `tracing_subscriber`.
+		fn make_writer(&'a self) -> Self::Writer {
+			self.writer()
+		}
+	}
+
+	/// Initialises a log capture utility for testing.
+	///
+	/// This function sets up a `LogCapture` instance to capture logs during test execution.
+	/// It also configures a `tracing_subscriber` with the specified maximum log level
+	/// and a writer that directs logs to `LogCapture`.
+	///
+	/// # Arguments
+	///
+	/// * `max_level` - The maximum log level to capture, which can be converted into `LevelFilter`.
+	///
+	/// # Returns
+	///
+	/// A tuple containing:
+	/// - `LogCapture`: The log capture instance.
+	/// - `Subscriber`: A configured `tracing_subscriber` that captures logs.
+	///
+	/// # Examples
+	///
+	/// ```
+	/// use sp_tracing::{
+	///     test_log_capture::init_log_capture,
+	///     tracing::{info, subscriber, Level},
+	/// };
+	///
+	/// let (log_capture, subscriber) = init_log_capture(Level::INFO);
+	/// subscriber::with_default(subscriber, || {
+	///     info!("This log will be captured");
+	///     assert!(log_capture.contains("This log will be captured"));
+	/// });
+	/// ```
+	pub fn init_log_capture(
+		max_level: impl Into<LevelFilter>,
+	) -> (LogCapture, Subscriber<DefaultFields, Format, LevelFilter, LogCapture>) {
+		// Create a new log capture instance
+		let log_capture = LogCapture::new();
+
+		// Configure a tracing subscriber to use the log capture as the writer
+		let subscriber = tracing_subscriber::fmt()
+			.with_max_level(max_level) // Set the max log level
+			.with_writer(log_capture.writer()) // Use LogCapture as the writer
+			.finish();
+
+		(log_capture, subscriber)
+	}
+
+	/// Macro for capturing logs during test execution.
+	///
+	/// It sets up a log subscriber with an optional maximum log level and captures the output.
+	///
+	/// # Examples
+	/// ```
+	/// use sp_tracing::{
+	///     capture_test_logs,
+	///     tracing::{info, warn, Level},
+	/// };
+	///
+	/// let log_capture = capture_test_logs!(Level::WARN, {
+	///     info!("Captured info message");
+	///     warn!("Captured warning");
+	/// });
+	///
+	/// assert!(!log_capture.contains("Captured log message"));
+	/// assert!(log_capture.contains("Captured warning"));
+	/// ```
+	#[macro_export]
+	macro_rules! capture_test_logs {
+		// Case when max_level is provided
+		($max_level:expr, $test:block) => {{
+			let (log_capture, subscriber) =
+				sp_tracing::test_log_capture::init_log_capture($max_level);
+
+			sp_tracing::tracing::subscriber::with_default(subscriber, || $test);
+
+			log_capture
+		}};
+
+		// Case when max_level is omitted (defaults to DEBUG)
+		($test:block) => {{
+			capture_test_logs!(sp_tracing::tracing::Level::DEBUG, $test)
+		}};
+	}
+}