diff --git a/Cargo.lock b/Cargo.lock index 5457e44aeaabe..a6b06ca731669 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -28017,6 +28017,7 @@ dependencies = [ "tracing", "tracing-core", "tracing-subscriber 0.3.18", + "tracing-test", ] [[package]] @@ -30692,6 +30693,27 @@ dependencies = [ "tracing-log 0.2.0", ] +[[package]] +name = "tracing-test" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "557b891436fe0d5e0e363427fc7f217abf9ccd510d5136549847bdcbcd011d68" +dependencies = [ + "tracing-core", + "tracing-subscriber 0.3.18", + "tracing-test-macro", +] + +[[package]] +name = "tracing-test-macro" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "04659ddb06c87d233c566112c1c9c5b9e98256d9af50ec3bc9c8327f873a7568" +dependencies = [ + "quote 1.0.38", + "syn 2.0.98", +] + [[package]] name = "trie-bench" version = "0.39.0" diff --git a/Cargo.toml b/Cargo.toml index b73e87d9bac26..fa10488801baa 100644 --- a/Cargo.toml +++ b/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 } diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index f971812f4f4d6..8937fcc03fffc 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/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::::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(); diff --git a/prdoc/pr_7594.prdoc b/prdoc/pr_7594.prdoc new file mode 100644 index 0000000000000..d79fc34ecdec9 --- /dev/null +++ b/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 diff --git a/substrate/primitives/tracing/Cargo.toml b/substrate/primitives/tracing/Cargo.toml index 8621582c76547..a874514b59062 100644 --- a/substrate/primitives/tracing/Cargo.toml +++ b/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"] @@ -37,6 +38,7 @@ std = [ "codec/std", "tracing-core/std", "tracing-subscriber", + "tracing-test", "tracing/std", "with-tracing", ] diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 21bba52d07ca0..e51e14e6df439 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/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: 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(max_level: impl Into, 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) + } +}