From d189f9e771d937999db4ed17cf2c5d9e1a6a29e7 Mon Sep 17 00:00:00 2001
From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com>
Date: Mon, 24 Feb 2025 14:47:32 +0000
Subject: [PATCH] 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>
---
polkadot/xcm/xcm-simulator/example/Cargo.toml | 3 +
.../xcm/xcm-simulator/example/src/tests.rs | 79 ++++++++
prdoc/pr_7594.prdoc | 12 ++
substrate/primitives/tracing/Cargo.toml | 1 +
substrate/primitives/tracing/src/lib.rs | 186 ++++++++++++++++++
5 files changed, 281 insertions(+)
create mode 100644 prdoc/pr_7594.prdoc
diff --git a/polkadot/xcm/xcm-simulator/example/Cargo.toml b/polkadot/xcm/xcm-simulator/example/Cargo.toml
index ccf0ecc39c4..fbee0718074 100644
--- a/polkadot/xcm/xcm-simulator/example/Cargo.toml
+++ b/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 }
diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs
index f971812f4f4..b39c63bd7da 100644
--- a/polkadot/xcm/xcm-simulator/example/src/tests.rs
+++ b/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()
+}
diff --git a/prdoc/pr_7594.prdoc b/prdoc/pr_7594.prdoc
new file mode 100644
index 00000000000..d79fc34ecde
--- /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 8621582c765..6c6cd1a3b6c 100644
--- a/substrate/primitives/tracing/Cargo.toml
+++ b/substrate/primitives/tracing/Cargo.toml
@@ -40,3 +40,4 @@ std = [
"tracing/std",
"with-tracing",
]
+test-utils = ["std"]
diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs
index 21bba52d07c..944f5f7ff43 100644
--- a/substrate/primitives/tracing/src/lib.rs
+++ b/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)
+ }};
+ }
+}
--
GitLab