Enhance XCM Debugging with Log Capture in Unit Tests

Cargo.toml

@@ -1364,6 +1364,7 @@ tracing-core = { version = "0.1.32", default-features = false }
 tracing-futures = { version = "0.2.4" }
 tracing-log = { version = "0.2.0" }
 tracing-subscriber = { version = "0.3.18" }
+tracing-test = { version = "0.2.5", default-features = false }
 tracking-allocator = { path = "polkadot/node/tracking-allocator", default-features = false, package = "staging-tracking-allocator" }
 trie-bench = { version = "0.39.0" }
 trie-db = { version = "0.29.1", default-features = false }

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

@@ -136,6 +136,28 @@ 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 = events
+			.iter()
+			.filter(|e| {
+				matches!(
+					e.event,
+					relay_chain::RuntimeEvent::XcmPallet(pallet_xcm::Event::Attempted { .. })
+				)
+			})
+			.count();
+		let sent_count = events
+			.iter()
+			.filter(|e| {
+				matches!(
+					e.event,
+					relay_chain::RuntimeEvent::XcmPallet(pallet_xcm::Event::Sent { .. })
+				)
+			})
+			.count();
+		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 +169,58 @@ fn reserve_transfer() {
 	});
 }
 
+#[test]
+fn reserve_transfer_with_error() {
+	use sp_tracing::{test_log_capture, tracing::Level};
+
+	// Reset the test network
+	MockNet::reset();
+
+	// Execute XCM Transfer and Capture Logs
+	test_log_capture::capture_with_max_level(Level::ERROR, || {
+		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");
+
+			// 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
+			);
+		});
+	});
+
+	// Assertions on Captured Logs
+	assert!(test_log_capture::logs_contain("XCM validate_send failed"));
+}
+
 #[test]
 fn remote_locking_and_unlocking() {
 	MockNet::reset();

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: patch

substrate/primitives/tracing/Cargo.toml

@@ -29,6 +29,7 @@ tracing-subscriber = { workspace = true, optional = true, features = [
 	"time",
 	"tracing-log",
 ] }
+tracing-test = { workspace = true, optional = true }
 
 [features]
 default = ["std"]
@@ -38,5 +39,6 @@ std = [
 	"tracing-core/std",
 	"tracing-subscriber",
 	"tracing/std",
+	"tracing-test",
 	"with-tracing",
 ]

substrate/primitives/tracing/src/lib.rs

@@ -255,3 +255,113 @@ macro_rules! enter_span {
 		$crate::enter_span!($crate::span!($lvl, $name))
 	};
 }
+
+/// `tracing-test` can be used for general logging capture but doesn't support logging within
+/// scoped functions like `Relay::execute_with`.
+///
+/// # Example
+///
+/// ```
+/// use tracing_test::traced_test;
+/// use tracing::info;
+///
+/// #[traced_test]
+/// fn test_logging() {
+///     info!("This is a test log message");
+///     assert!(logs_contain("test log message"));
+/// }
+/// ```
+///
+/// For more details, see [`tracing-test`](https://crates.io/crates/tracing-test).
+#[cfg(feature = "std")]
+pub use tracing_test;
+
+/// A module for capturing and asserting logs in tests.
+///
+/// This module provides utilities for capturing logs during test execution
+/// and verifying expected log output.
+///
+/// # Example
+///
+/// ```
+/// use sp_tracing::test_log_capture;
+///
+/// test_log_capture::capture(|| {
+///     tracing::info!("This is a test log message");
+/// });
+///
+/// assert!(test_log_capture::logs_contain("test log message"));
+/// ```
+#[cfg(feature = "std")]
+pub mod test_log_capture {
+	use tracing::subscriber;
+	use tracing_core::LevelFilter;
+	use tracing_test::internal::{global_buf, MockWriter};
+
+	/// Runs a test block with logging enabled and captures logs for assertions.
+	///
+	/// This function sets up a `tracing_subscriber` that redirects logs
+	/// to an internal buffer, which can later be queried.
+	///
+	/// # Example
+	///
+	/// ```
+	/// use sp_tracing::test_log_capture;
+	///
+	/// test_log_capture::capture(|| {
+	///     tracing::warn!("Captured warning message");
+	/// });
+	///
+	/// assert!(test_log_capture::logs_contain("Captured warning message"));
+	/// ```
+	pub fn capture<F: FnOnce()>(f: F) {
+		capture_with_max_level(LevelFilter::DEBUG, f);
+	}
+
+	/// Runs a test block with logging enabled and captures logs for assertions
+	/// while allowing the maximum log level to be specified.
+	///
+	/// # Example
+	///
+	/// ```
+	/// use sp_tracing::test_log_capture;
+	/// use sp_tracing::tracing::Level;
+	///
+	/// test_log_capture::capture_with_max_level(Level::INFO, || {
+	///     tracing::info!("This will be captured at INFO level");
+	///     tracing::debug!("This will be captured at DEBUG level");
+	/// });
+	///
+	///  assert!(test_log_capture::logs_contain("INFO level"));
+	///  assert!(!test_log_capture::logs_contain("DEBUG level"));
+	/// ```
+	pub fn capture_with_max_level<F: FnOnce()>(max_level: impl Into<LevelFilter>, f: F) {
+		let log_capture = MockWriter::new(&global_buf());
+		let subscriber = tracing_subscriber::fmt()
+			.with_max_level(max_level)
+			.with_writer(log_capture)
+			.finish();
+		subscriber::with_default(subscriber, f);
+	}
+
+	/// Checks whether a captured log message contains a given substring.
+	///
+	/// This function retrieves all captured logs and checks if the provided
+	/// string is present.
+	///
+	/// # Example
+	///
+	/// ```
+	/// use sp_tracing::test_log_capture;
+	///
+	/// test_log_capture::capture(|| {
+	///     tracing::debug!("Debug log for testing");
+	/// });
+	///
+	/// assert!(test_log_capture::logs_contain("Debug log"));
+	/// ```
+	pub fn logs_contain(value: &str) -> bool {
+		let logs = String::from_utf8(global_buf().lock().unwrap().clone()).unwrap();
+		logs.contains(value)
+	}
+}