From 624c15a0077e67db11e3fd595a0ddb0514e1acc1 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Thu, 13 Feb 2025 14:34:24 +0000 Subject: [PATCH 01/24] Assert on captured logs on XCM Simulator --- Cargo.lock | 22 ++++ polkadot/xcm/pallet-xcm/src/tests/mod.rs | 100 +++++++++++++++++ polkadot/xcm/xcm-simulator/example/Cargo.toml | 4 +- .../xcm/xcm-simulator/example/src/tests.rs | 105 ++++++++++++++++++ 4 files changed, 230 insertions(+), 1 deletion(-) diff --git a/Cargo.lock b/Cargo.lock index 40594efe42d3a..a4b9acd8e0cd0 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -30368,6 +30368,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" @@ -32200,6 +32221,7 @@ dependencies = [ "staging-xcm 7.0.0", "staging-xcm-builder 7.0.0", "staging-xcm-executor 7.0.0", + "tracing-test", "xcm-simulator 7.0.0", ] diff --git a/polkadot/xcm/pallet-xcm/src/tests/mod.rs b/polkadot/xcm/pallet-xcm/src/tests/mod.rs index 350530f7711f8..74cb2c78e9b15 100644 --- a/polkadot/xcm/pallet-xcm/src/tests/mod.rs +++ b/polkadot/xcm/pallet-xcm/src/tests/mod.rs @@ -361,6 +361,106 @@ fn send_fails_when_xcm_router_blocks() { }); } +/// Test for Emitting Events on `DispatchError` +#[test] +fn emit_event_on_dispatch_error() { + let balances = vec![ + (ALICE, INITIAL_BALANCE), + (ParaId::from(OTHER_PARA_ID).into_account_truncating(), INITIAL_BALANCE), + ]; + new_test_ext_with_balances(balances).execute_with(|| { + let sender: Location = Junction::AccountId32 { network: None, id: ALICE.into() }.into(); + let message = Xcm(vec![ + ReserveAssetDeposited((Parent, SEND_AMOUNT).into()), + // Introduce an error by using an invalid instruction + WithdrawAsset((Parent, 0).into()), // Invalid amount + DepositAsset { assets: AllCounted(1).into(), beneficiary: sender.clone() }, + ]); + + let result = XcmPallet::send( + RuntimeOrigin::signed(ALICE), + Box::new(Location::ancestor(8).into()), + Box::new(VersionedXcm::from(message.clone())), + ); + + // Ensure the send fails + assert_noop!(result, crate::Error::::SendFailure); + + // Check if the error event is emitted + let events = System::events(); + assert!( + events.iter().any(|record| matches!( + record.event, + RuntimeEvent::XcmPallet(crate::Event::Failed { .. }) + )), + "Expected a Failed event to be emitted" + ); + }); +} + +/// Test for Emitting Events on Query Response +#[test] +fn emit_event_on_query_response() { + let balances = vec![ + (ALICE, INITIAL_BALANCE), + (ParaId::from(OTHER_PARA_ID).into_account_truncating(), INITIAL_BALANCE), + ]; + new_test_ext_with_balances(balances).execute_with(|| { + let sender: Location = AccountId32 { network: None, id: ALICE.into() }.into(); + let mut message = Xcm(vec![TransferAsset { + assets: (Here, SEND_AMOUNT).into(), + beneficiary: sender.clone(), + }]); + let call = pallet_test_notifier::Call::notification_received { + query_id: 0, + response: Default::default(), + }; + let notify = RuntimeCall::TestNotifier(call); + XcmPallet::report_outcome_notify( + &mut message, + Parachain(OTHER_PARA_ID).into_location(), + notify, + 100, + ) + .unwrap(); + + let querier: Location = Here.into(); + let status = QueryStatus::Pending { + responder: Location::from(Parachain(OTHER_PARA_ID)).into(), + maybe_notify: Some((5, 2)), + timeout: 100, + maybe_match_querier: Some(querier.clone().into()), + }; + assert_eq!(crate::Queries::::iter().collect::>(), vec![(0, status)]); + + let message = Xcm(vec![QueryResponse { + query_id: 0, + response: Response::ExecutionResult(None), + max_weight: Weight::from_parts(1_000_000, 1_000_000), + querier: Some(querier), + }]); + let mut hash = fake_message_hash(&message); + let r = XcmExecutor::::prepare_and_execute( + Parachain(OTHER_PARA_ID), + message, + &mut hash, + Weight::from_parts(1_000_000_000, 1_000_000_000), + Weight::zero(), + ); + assert_eq!(r, Outcome::Complete { used: Weight::from_parts(1_000, 1_000) }); + + // Check if the response event is emitted + let events = System::events(); + assert!( + events.iter().any(|record| matches!( + record.event, + RuntimeEvent::XcmPallet(crate::Event::ResponseReady { .. }) + )), + "Expected a ResponseReady event to be emitted" + ); + }); +} + /// Test local execution of XCM /// /// Asserts that the sender's balance is decreased and the beneficiary's balance diff --git a/polkadot/xcm/xcm-simulator/example/Cargo.toml b/polkadot/xcm/xcm-simulator/example/Cargo.toml index ccf0ecc39c4c8..3de8a17710580 100644 --- a/polkadot/xcm/xcm-simulator/example/Cargo.toml +++ b/polkadot/xcm/xcm-simulator/example/Cargo.toml @@ -14,7 +14,9 @@ workspace = true [dependencies] codec = { workspace = true, default-features = true } log = { workspace = true } -scale-info = { features = ["derive"], workspace = true, default-features = true } +scale-info = { features = [ + "derive", +], workspace = true, default-features = true } frame-support = { workspace = true, default-features = true } frame-system = { workspace = true, default-features = true } diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index f971812f4f4d6..dc6bb1dd1d122 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -18,6 +18,7 @@ use crate::*; use codec::Encode; use frame_support::{assert_ok, weights::Weight}; +use tracing_test::internal::global_buf; use xcm::latest::QueryResponseInfo; use xcm_simulator::{mock_message_queue::ReceivedDmp, TestExt}; @@ -511,3 +512,107 @@ fn query_holding() { ); }); } + +#[test] +fn reserve_transfer_with_error() { + use sp_tracing::{ + tracing::subscriber, + tracing_subscriber, + tracing_subscriber::fmt::MakeWriter, + }; + use std::{ + io::Write, + sync::{Arc, Mutex}, + }; + + // Reset the test network + MockNet::reset(); + + // **Custom Log Capturing Writer** + struct StringWriter(Arc>>); + + impl Write for StringWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + self.0.lock().unwrap().extend_from_slice(buf); + Ok(buf.len()) + } + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } + + // **Implement MakeWriter for StringWriter** + impl<'a> MakeWriter<'a> for StringWriter { + type Writer = Self; + + fn make_writer(&'a self) -> Self::Writer { + StringWriter(self.0.clone()) // Clone Arc to allow multiple writers + } + } + + struct LogCapture { + buffer: Arc>>, + } + + impl Write for LogCapture { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let mut logs = self.buffer.lock().unwrap(); + logs.extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } + + impl<'a> MakeWriter<'a> for LogCapture { + type Writer = Self; + + fn make_writer(&'a self) -> Self::Writer { + LogCapture { buffer: Arc::clone(&self.buffer) } + } + } + + let log_buffer = Arc::new(Mutex::new(Vec::new())); + let writer = LogCapture { buffer: Arc::clone(&log_buffer) }; + + let subscriber = tracing_subscriber::fmt() + .with_writer(writer) // Redirect logs to custom writer + .finish(); + + // **Execute the XCM transfer** + subscriber::with_default(subscriber, || { + Relay::execute_with(|| { + let invalid_dest = Box::new(Parachain(9999).into()); + 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, 123u128).into()), + 0, + Unlimited, + ); + + // Ensure an error occurred + assert!(result.is_err(), "Expected an error due to invalid destination"); + }); + + ParaA::execute_with(|| { + // Ensure no balance change due to the error + assert_eq!( + pallet_balances::Pallet::::free_balance(&ALICE), + INITIAL_BALANCE + ); + }); + }); + + // **Retrieve Captured Logs** + let logs = String::from_utf8(log_buffer.lock().unwrap().clone()).unwrap(); + + // **Assertions on Logs** + assert!( + logs.contains("XCM validate_send failed"), + "Expected 'XCM validate_send failed' in logs." + ); +} From 513b1774a2d701251bfa40ee5221793b068f15b9 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Mon, 17 Feb 2025 15:58:26 +0000 Subject: [PATCH 02/24] Remove tests for DispatchError --- Cargo.lock | 22 ---- polkadot/xcm/pallet-xcm/src/tests/mod.rs | 100 ------------------ .../xcm/xcm-simulator/example/src/tests.rs | 54 ++-------- 3 files changed, 11 insertions(+), 165 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index a4b9acd8e0cd0..40594efe42d3a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -30368,27 +30368,6 @@ 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" @@ -32221,7 +32200,6 @@ dependencies = [ "staging-xcm 7.0.0", "staging-xcm-builder 7.0.0", "staging-xcm-executor 7.0.0", - "tracing-test", "xcm-simulator 7.0.0", ] diff --git a/polkadot/xcm/pallet-xcm/src/tests/mod.rs b/polkadot/xcm/pallet-xcm/src/tests/mod.rs index 74cb2c78e9b15..350530f7711f8 100644 --- a/polkadot/xcm/pallet-xcm/src/tests/mod.rs +++ b/polkadot/xcm/pallet-xcm/src/tests/mod.rs @@ -361,106 +361,6 @@ fn send_fails_when_xcm_router_blocks() { }); } -/// Test for Emitting Events on `DispatchError` -#[test] -fn emit_event_on_dispatch_error() { - let balances = vec![ - (ALICE, INITIAL_BALANCE), - (ParaId::from(OTHER_PARA_ID).into_account_truncating(), INITIAL_BALANCE), - ]; - new_test_ext_with_balances(balances).execute_with(|| { - let sender: Location = Junction::AccountId32 { network: None, id: ALICE.into() }.into(); - let message = Xcm(vec![ - ReserveAssetDeposited((Parent, SEND_AMOUNT).into()), - // Introduce an error by using an invalid instruction - WithdrawAsset((Parent, 0).into()), // Invalid amount - DepositAsset { assets: AllCounted(1).into(), beneficiary: sender.clone() }, - ]); - - let result = XcmPallet::send( - RuntimeOrigin::signed(ALICE), - Box::new(Location::ancestor(8).into()), - Box::new(VersionedXcm::from(message.clone())), - ); - - // Ensure the send fails - assert_noop!(result, crate::Error::::SendFailure); - - // Check if the error event is emitted - let events = System::events(); - assert!( - events.iter().any(|record| matches!( - record.event, - RuntimeEvent::XcmPallet(crate::Event::Failed { .. }) - )), - "Expected a Failed event to be emitted" - ); - }); -} - -/// Test for Emitting Events on Query Response -#[test] -fn emit_event_on_query_response() { - let balances = vec![ - (ALICE, INITIAL_BALANCE), - (ParaId::from(OTHER_PARA_ID).into_account_truncating(), INITIAL_BALANCE), - ]; - new_test_ext_with_balances(balances).execute_with(|| { - let sender: Location = AccountId32 { network: None, id: ALICE.into() }.into(); - let mut message = Xcm(vec![TransferAsset { - assets: (Here, SEND_AMOUNT).into(), - beneficiary: sender.clone(), - }]); - let call = pallet_test_notifier::Call::notification_received { - query_id: 0, - response: Default::default(), - }; - let notify = RuntimeCall::TestNotifier(call); - XcmPallet::report_outcome_notify( - &mut message, - Parachain(OTHER_PARA_ID).into_location(), - notify, - 100, - ) - .unwrap(); - - let querier: Location = Here.into(); - let status = QueryStatus::Pending { - responder: Location::from(Parachain(OTHER_PARA_ID)).into(), - maybe_notify: Some((5, 2)), - timeout: 100, - maybe_match_querier: Some(querier.clone().into()), - }; - assert_eq!(crate::Queries::::iter().collect::>(), vec![(0, status)]); - - let message = Xcm(vec![QueryResponse { - query_id: 0, - response: Response::ExecutionResult(None), - max_weight: Weight::from_parts(1_000_000, 1_000_000), - querier: Some(querier), - }]); - let mut hash = fake_message_hash(&message); - let r = XcmExecutor::::prepare_and_execute( - Parachain(OTHER_PARA_ID), - message, - &mut hash, - Weight::from_parts(1_000_000_000, 1_000_000_000), - Weight::zero(), - ); - assert_eq!(r, Outcome::Complete { used: Weight::from_parts(1_000, 1_000) }); - - // Check if the response event is emitted - let events = System::events(); - assert!( - events.iter().any(|record| matches!( - record.event, - RuntimeEvent::XcmPallet(crate::Event::ResponseReady { .. }) - )), - "Expected a ResponseReady event to be emitted" - ); - }); -} - /// Test local execution of XCM /// /// Asserts that the sender's balance is decreased and the beneficiary's balance diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index dc6bb1dd1d122..cba28a60229f7 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -18,7 +18,6 @@ use crate::*; use codec::Encode; use frame_support::{assert_ok, weights::Weight}; -use tracing_test::internal::global_buf; use xcm::latest::QueryResponseInfo; use xcm_simulator::{mock_message_queue::ReceivedDmp, TestExt}; @@ -515,49 +514,22 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::{ - tracing::subscriber, - tracing_subscriber, - tracing_subscriber::fmt::MakeWriter, - }; + use sp_tracing::{tracing::subscriber, tracing_subscriber}; use std::{ io::Write, sync::{Arc, Mutex}, }; + use tracing_subscriber::fmt::MakeWriter; // Reset the test network MockNet::reset(); - // **Custom Log Capturing Writer** - struct StringWriter(Arc>>); - - impl Write for StringWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - self.0.lock().unwrap().extend_from_slice(buf); - Ok(buf.len()) - } - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) - } - } - - // **Implement MakeWriter for StringWriter** - impl<'a> MakeWriter<'a> for StringWriter { - type Writer = Self; - - fn make_writer(&'a self) -> Self::Writer { - StringWriter(self.0.clone()) // Clone Arc to allow multiple writers - } - } - - struct LogCapture { - buffer: Arc>>, - } + // Custom Log Capturing Writer + struct LogCapture(Arc>>); impl Write for LogCapture { fn write(&mut self, buf: &[u8]) -> std::io::Result { - let mut logs = self.buffer.lock().unwrap(); - logs.extend_from_slice(buf); + self.0.lock().unwrap().extend_from_slice(buf); Ok(buf.len()) } @@ -568,20 +540,18 @@ fn reserve_transfer_with_error() { impl<'a> MakeWriter<'a> for LogCapture { type Writer = Self; - fn make_writer(&'a self) -> Self::Writer { - LogCapture { buffer: Arc::clone(&self.buffer) } + LogCapture(Arc::clone(&self.0)) } } + // Initialise Log Capture let log_buffer = Arc::new(Mutex::new(Vec::new())); - let writer = LogCapture { buffer: Arc::clone(&log_buffer) }; - let subscriber = tracing_subscriber::fmt() - .with_writer(writer) // Redirect logs to custom writer + .with_writer(LogCapture(Arc::clone(&log_buffer))) .finish(); - // **Execute the XCM transfer** + // Execute XCM Transfer and Capture Logs subscriber::with_default(subscriber, || { Relay::execute_with(|| { let invalid_dest = Box::new(Parachain(9999).into()); @@ -598,8 +568,8 @@ fn reserve_transfer_with_error() { assert!(result.is_err(), "Expected an error due to invalid destination"); }); + // Ensure no balance change due to the error ParaA::execute_with(|| { - // Ensure no balance change due to the error assert_eq!( pallet_balances::Pallet::::free_balance(&ALICE), INITIAL_BALANCE @@ -607,10 +577,8 @@ fn reserve_transfer_with_error() { }); }); - // **Retrieve Captured Logs** + // Assertions on Captured Logs let logs = String::from_utf8(log_buffer.lock().unwrap().clone()).unwrap(); - - // **Assertions on Logs** assert!( logs.contains("XCM validate_send failed"), "Expected 'XCM validate_send failed' in logs." From 489247be53b2bcd19e7592d07fd69a75eab749b0 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Mon, 17 Feb 2025 15:59:19 +0000 Subject: [PATCH 03/24] Revert Cargo.toml --- polkadot/xcm/xcm-simulator/example/Cargo.toml | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/Cargo.toml b/polkadot/xcm/xcm-simulator/example/Cargo.toml index 3de8a17710580..ccf0ecc39c4c8 100644 --- a/polkadot/xcm/xcm-simulator/example/Cargo.toml +++ b/polkadot/xcm/xcm-simulator/example/Cargo.toml @@ -14,9 +14,7 @@ workspace = true [dependencies] codec = { workspace = true, default-features = true } log = { workspace = true } -scale-info = { features = [ - "derive", -], workspace = true, default-features = true } +scale-info = { features = ["derive"], workspace = true, default-features = true } frame-support = { workspace = true, default-features = true } frame-system = { workspace = true, default-features = true } From ce94bff64d40ca42e0bd5b9d48029462387ea1bc Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Mon, 17 Feb 2025 17:06:38 +0000 Subject: [PATCH 04/24] Add log_capture --- polkadot/xcm/xcm-simulator/example/src/lib.rs | 75 ++++++++++++++++++- .../xcm/xcm-simulator/example/src/tests.rs | 42 +---------- 2 files changed, 77 insertions(+), 40 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/lib.rs b/polkadot/xcm/xcm-simulator/example/src/lib.rs index 8a05569831b5c..ddb4f80d45c29 100644 --- a/polkadot/xcm/xcm-simulator/example/src/lib.rs +++ b/polkadot/xcm/xcm-simulator/example/src/lib.rs @@ -21,7 +21,12 @@ mod relay_chain; mod tests; use sp_runtime::BuildStorage; -use sp_tracing; +use sp_tracing::{self, tracing_subscriber}; +use std::{ + io::Write, + sync::{Arc, Mutex}, +}; +use tracing_subscriber::fmt::MakeWriter; use xcm::prelude::*; use xcm_executor::traits::ConvertLocation; use xcm_simulator::{decl_test_network, decl_test_parachain, decl_test_relay_chain, TestExt}; @@ -29,6 +34,74 @@ use xcm_simulator::{decl_test_network, decl_test_parachain, decl_test_relay_chai pub const ALICE: sp_runtime::AccountId32 = sp_runtime::AccountId32::new([1u8; 32]); pub const INITIAL_BALANCE: u128 = 1_000_000_000; +/// A reusable log capturing struct for unit tests. +pub struct LogCapture { + buffer: Arc>>, +} + +impl LogCapture { + /// Creates a new LogCapture instance with an internal buffer. + pub fn new() -> Self { + LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) } + } + + /// Retrieves the captured logs as a String. + 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 { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let mut logs = self.buffer.lock().unwrap(); + logs.extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +impl<'a> MakeWriter<'a> for LogCapture { + type Writer = Self; + + fn make_writer(&'a self) -> Self::Writer { + self.writer() + } +} + +#[macro_export] +macro_rules! run_with_logging { + ($test:block) => {{ + let log_capture = LogCapture::new(); + let subscriber = tracing_subscriber::fmt().with_writer(log_capture.writer()).finish(); + + tracing::subscriber::with_default(subscriber, || $test); + + log_capture + }}; +} + +/// Macro to assert that captured logs contain a specific substring. +#[macro_export] +macro_rules! assert_logs_contain { + ($log_capture:expr, $expected:expr) => { + let logs = $log_capture.get_logs(); + assert!( + logs.contains($expected), + "Expected '{}' in logs, but logs were:\n{}", + $expected, + logs + ); + }; +} + decl_test_parachain! { pub struct ParaA { Runtime = parachain::Runtime, diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index cba28a60229f7..2518a3d09e6f5 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -514,45 +514,13 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::{tracing::subscriber, tracing_subscriber}; - use std::{ - io::Write, - sync::{Arc, Mutex}, - }; - use tracing_subscriber::fmt::MakeWriter; + use sp_tracing::{tracing, tracing_subscriber}; // Reset the test network MockNet::reset(); - // Custom Log Capturing Writer - struct LogCapture(Arc>>); - - impl Write for LogCapture { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - self.0.lock().unwrap().extend_from_slice(buf); - Ok(buf.len()) - } - - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) - } - } - - impl<'a> MakeWriter<'a> for LogCapture { - type Writer = Self; - fn make_writer(&'a self) -> Self::Writer { - LogCapture(Arc::clone(&self.0)) - } - } - - // Initialise Log Capture - let log_buffer = Arc::new(Mutex::new(Vec::new())); - let subscriber = tracing_subscriber::fmt() - .with_writer(LogCapture(Arc::clone(&log_buffer))) - .finish(); - // Execute XCM Transfer and Capture Logs - subscriber::with_default(subscriber, || { + let log_capture = run_with_logging!({ Relay::execute_with(|| { let invalid_dest = Box::new(Parachain(9999).into()); let result = RelayChainPalletXcm::limited_reserve_transfer_assets( @@ -578,9 +546,5 @@ fn reserve_transfer_with_error() { }); // Assertions on Captured Logs - let logs = String::from_utf8(log_buffer.lock().unwrap().clone()).unwrap(); - assert!( - logs.contains("XCM validate_send failed"), - "Expected 'XCM validate_send failed' in logs." - ); + assert_logs_contain!(log_capture, "XCM validate_send failed"); } From 9bd8d154d5f4e98383bb2479fa517a678ef40628 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Mon, 17 Feb 2025 17:11:01 +0000 Subject: [PATCH 05/24] Add docs for LogCapture --- polkadot/xcm/xcm-simulator/example/src/lib.rs | 20 ++++++++++++++++--- 1 file changed, 17 insertions(+), 3 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/lib.rs b/polkadot/xcm/xcm-simulator/example/src/lib.rs index ddb4f80d45c29..a9b849c8c9c9b 100644 --- a/polkadot/xcm/xcm-simulator/example/src/lib.rs +++ b/polkadot/xcm/xcm-simulator/example/src/lib.rs @@ -35,22 +35,23 @@ pub const ALICE: sp_runtime::AccountId32 = sp_runtime::AccountId32::new([1u8; 32 pub const INITIAL_BALANCE: u128 = 1_000_000_000; /// A reusable log capturing struct for unit tests. +/// Captures logs written during test execution for assertions. pub struct LogCapture { buffer: Arc>>, } impl LogCapture { - /// Creates a new LogCapture instance with an internal buffer. + /// Creates a new `LogCapture` instance with an internal buffer. pub fn new() -> Self { LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) } } - /// Retrieves the captured logs as a String. + /// Retrieves the captured logs as a `String`. 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` + /// Returns a clone of the internal buffer for use in `MakeWriter`. pub fn writer(&self) -> Self { LogCapture { buffer: Arc::clone(&self.buffer) } } @@ -71,11 +72,20 @@ impl Write for LogCapture { 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() } } +/// Runs a test block with logging enabled and captures logs for assertions. +/// Usage: +/// ```ignore +/// let log_capture = run_with_logging!({ +/// my_test_function(); +/// }); +/// assert_logs_contain!(log_capture, "Expected log message"); +/// ``` #[macro_export] macro_rules! run_with_logging { ($test:block) => {{ @@ -89,6 +99,10 @@ macro_rules! run_with_logging { } /// Macro to assert that captured logs contain a specific substring. +/// Usage: +/// ```ignore +/// assert_logs_contain!(log_capture, "Expected log message"); +/// ``` #[macro_export] macro_rules! assert_logs_contain { ($log_capture:expr, $expected:expr) => { From 6500072c18027b569ad46213831dad26074f06f7 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 10:40:10 +0000 Subject: [PATCH 06/24] Add tracing-test --- Cargo.lock | 22 ++++++++++++++++++++++ Cargo.toml | 1 + substrate/primitives/tracing/Cargo.toml | 2 ++ substrate/primitives/tracing/src/lib.rs | 4 ++++ 4 files changed, 29 insertions(+) diff --git a/Cargo.lock b/Cargo.lock index c6fefcfdfe186..5d4345432abea 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -27808,6 +27808,7 @@ dependencies = [ "tracing", "tracing-core", "tracing-subscriber 0.3.18", + "tracing-test", ] [[package]] @@ -30433,6 +30434,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 0769a95932d44..5b2d6f92e9ad7 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1365,6 +1365,7 @@ tracing-futures = { version = "0.2.4" } tracing-log = { version = "0.2.0" } tracing-subscriber = { version = "0.3.18" } tracking-allocator = { path = "polkadot/node/tracking-allocator", default-features = false, package = "staging-tracking-allocator" } +tracing-test = { version = "0.2.5", default-features = false } trie-bench = { version = "0.39.0" } trie-db = { version = "0.29.1", default-features = false } trie-root = { version = "0.18.0", default-features = false } diff --git a/substrate/primitives/tracing/Cargo.toml b/substrate/primitives/tracing/Cargo.toml index 8621582c76547..f07818cba73e5 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"] @@ -38,5 +39,6 @@ std = [ "tracing-core/std", "tracing-subscriber", "tracing/std", + "tracing-test", "with-tracing", ] diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 21bba52d07ca0..400679bbec236 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -255,3 +255,7 @@ macro_rules! enter_span { $crate::enter_span!($crate::span!($lvl, $name)) }; } + +#[cfg(feature = "std")] +pub use tracing_test; + From c4572f2e08fcae1825cf70a6f2563812aab26b93 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 11:18:09 +0000 Subject: [PATCH 07/24] Add changes --- polkadot/xcm/xcm-simulator/example/src/lib.rs | 16 ++++++++++---- .../xcm/xcm-simulator/example/src/tests.rs | 22 +++++++++++++++++++ substrate/primitives/tracing/src/lib.rs | 1 - 3 files changed, 34 insertions(+), 5 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/lib.rs b/polkadot/xcm/xcm-simulator/example/src/lib.rs index a9b849c8c9c9b..6d4c3242a01a0 100644 --- a/polkadot/xcm/xcm-simulator/example/src/lib.rs +++ b/polkadot/xcm/xcm-simulator/example/src/lib.rs @@ -30,6 +30,7 @@ use tracing_subscriber::fmt::MakeWriter; use xcm::prelude::*; use xcm_executor::traits::ConvertLocation; use xcm_simulator::{decl_test_network, decl_test_parachain, decl_test_relay_chain, TestExt}; +use sp_tracing::tracing_test::internal::MockWriter; pub const ALICE: sp_runtime::AccountId32 = sp_runtime::AccountId32::new([1u8; 32]); pub const INITIAL_BALANCE: u128 = 1_000_000_000; @@ -38,12 +39,19 @@ pub const INITIAL_BALANCE: u128 = 1_000_000_000; /// Captures logs written during test execution for assertions. pub struct LogCapture { buffer: Arc>>, + writer: MockWriter<'static>, } impl LogCapture { /// Creates a new `LogCapture` instance with an internal buffer. pub fn new() -> Self { - LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) } + let buffer = Arc::new(Mutex::new(Vec::new())); + + // Convert Arc to a leaked 'static reference + let buffer_static: &'static Mutex> = Box::leak(Box::new(Mutex::new(Vec::new()))); + let writer = MockWriter::new(buffer_static); + + LogCapture { buffer, writer } } /// Retrieves the captured logs as a `String`. @@ -52,8 +60,8 @@ impl LogCapture { } /// Returns a clone of the internal buffer for use in `MakeWriter`. - pub fn writer(&self) -> Self { - LogCapture { buffer: Arc::clone(&self.buffer) } + pub fn writer(&self) -> MockWriter { + MockWriter::new(unsafe { &*(Arc::as_ptr(&self.buffer)) }) } } @@ -70,7 +78,7 @@ impl Write for LogCapture { } impl<'a> MakeWriter<'a> for LogCapture { - type Writer = Self; + type Writer = MockWriter<'a>; /// Provides a `MakeWriter` implementation for `tracing_subscriber`. fn make_writer(&'a self) -> Self::Writer { diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 2518a3d09e6f5..4ec9fa681adf3 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -515,10 +515,32 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { use sp_tracing::{tracing, tracing_subscriber}; + use std::sync::{Arc, Mutex}; // Reset the test network MockNet::reset(); + // let buffer = Arc::new(Mutex::new(Vec::new())); + // let buffer_static: &'static Arc>> = Box::leak(Box::new(buffer.clone())); + // let mock_writer = sp_tracing::tracing_test::internal::MockWriter::new(&buffer_static); + // let subscriber = tracing_subscriber::fmt().with_writer(mock_writer).finish(); + // tracing::subscriber::with_default(subscriber, || { + // let invalid_dest = Box::new(Parachain(9999).into()); + // 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, 123u128).into()), + // 0, + // Unlimited, + // ); + // + // // Ensure an error occurred + // assert!(result.is_err(), "Expected an error due to invalid destination"); + // }); + // let logs = String::from_utf8(buffer.lock().unwrap().clone()).unwrap(); + // assert!(logs.contains("XCM validate_send failed")); + // Execute XCM Transfer and Capture Logs let log_capture = run_with_logging!({ Relay::execute_with(|| { diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 400679bbec236..2a48e052c9611 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -258,4 +258,3 @@ macro_rules! enter_span { #[cfg(feature = "std")] pub use tracing_test; - From 286cd2f6931bcb132f83f1b8abec47babcc1fbda Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 11:30:41 +0000 Subject: [PATCH 08/24] Add changes --- polkadot/xcm/xcm-simulator/example/src/lib.rs | 16 ++++------------ 1 file changed, 4 insertions(+), 12 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/lib.rs b/polkadot/xcm/xcm-simulator/example/src/lib.rs index 6d4c3242a01a0..a9b849c8c9c9b 100644 --- a/polkadot/xcm/xcm-simulator/example/src/lib.rs +++ b/polkadot/xcm/xcm-simulator/example/src/lib.rs @@ -30,7 +30,6 @@ use tracing_subscriber::fmt::MakeWriter; use xcm::prelude::*; use xcm_executor::traits::ConvertLocation; use xcm_simulator::{decl_test_network, decl_test_parachain, decl_test_relay_chain, TestExt}; -use sp_tracing::tracing_test::internal::MockWriter; pub const ALICE: sp_runtime::AccountId32 = sp_runtime::AccountId32::new([1u8; 32]); pub const INITIAL_BALANCE: u128 = 1_000_000_000; @@ -39,19 +38,12 @@ pub const INITIAL_BALANCE: u128 = 1_000_000_000; /// Captures logs written during test execution for assertions. pub struct LogCapture { buffer: Arc>>, - writer: MockWriter<'static>, } impl LogCapture { /// Creates a new `LogCapture` instance with an internal buffer. pub fn new() -> Self { - let buffer = Arc::new(Mutex::new(Vec::new())); - - // Convert Arc to a leaked 'static reference - let buffer_static: &'static Mutex> = Box::leak(Box::new(Mutex::new(Vec::new()))); - let writer = MockWriter::new(buffer_static); - - LogCapture { buffer, writer } + LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) } } /// Retrieves the captured logs as a `String`. @@ -60,8 +52,8 @@ impl LogCapture { } /// Returns a clone of the internal buffer for use in `MakeWriter`. - pub fn writer(&self) -> MockWriter { - MockWriter::new(unsafe { &*(Arc::as_ptr(&self.buffer)) }) + pub fn writer(&self) -> Self { + LogCapture { buffer: Arc::clone(&self.buffer) } } } @@ -78,7 +70,7 @@ impl Write for LogCapture { } impl<'a> MakeWriter<'a> for LogCapture { - type Writer = MockWriter<'a>; + type Writer = Self; /// Provides a `MakeWriter` implementation for `tracing_subscriber`. fn make_writer(&'a self) -> Self::Writer { From b8aa3772d362c1254f7ba2d394025738de58f99d Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 11:38:24 +0000 Subject: [PATCH 09/24] Revert changes --- Cargo.lock | 22 ------------------- Cargo.toml | 1 - .../xcm/xcm-simulator/example/src/tests.rs | 22 ------------------- substrate/primitives/tracing/Cargo.toml | 2 -- substrate/primitives/tracing/src/lib.rs | 3 --- 5 files changed, 50 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5d4345432abea..c6fefcfdfe186 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -27808,7 +27808,6 @@ dependencies = [ "tracing", "tracing-core", "tracing-subscriber 0.3.18", - "tracing-test", ] [[package]] @@ -30434,27 +30433,6 @@ 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 5b2d6f92e9ad7..0769a95932d44 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1365,7 +1365,6 @@ tracing-futures = { version = "0.2.4" } tracing-log = { version = "0.2.0" } tracing-subscriber = { version = "0.3.18" } tracking-allocator = { path = "polkadot/node/tracking-allocator", default-features = false, package = "staging-tracking-allocator" } -tracing-test = { version = "0.2.5", default-features = false } trie-bench = { version = "0.39.0" } trie-db = { version = "0.29.1", default-features = false } trie-root = { version = "0.18.0", default-features = false } diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 4ec9fa681adf3..2518a3d09e6f5 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -515,32 +515,10 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { use sp_tracing::{tracing, tracing_subscriber}; - use std::sync::{Arc, Mutex}; // Reset the test network MockNet::reset(); - // let buffer = Arc::new(Mutex::new(Vec::new())); - // let buffer_static: &'static Arc>> = Box::leak(Box::new(buffer.clone())); - // let mock_writer = sp_tracing::tracing_test::internal::MockWriter::new(&buffer_static); - // let subscriber = tracing_subscriber::fmt().with_writer(mock_writer).finish(); - // tracing::subscriber::with_default(subscriber, || { - // let invalid_dest = Box::new(Parachain(9999).into()); - // 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, 123u128).into()), - // 0, - // Unlimited, - // ); - // - // // Ensure an error occurred - // assert!(result.is_err(), "Expected an error due to invalid destination"); - // }); - // let logs = String::from_utf8(buffer.lock().unwrap().clone()).unwrap(); - // assert!(logs.contains("XCM validate_send failed")); - // Execute XCM Transfer and Capture Logs let log_capture = run_with_logging!({ Relay::execute_with(|| { diff --git a/substrate/primitives/tracing/Cargo.toml b/substrate/primitives/tracing/Cargo.toml index f07818cba73e5..8621582c76547 100644 --- a/substrate/primitives/tracing/Cargo.toml +++ b/substrate/primitives/tracing/Cargo.toml @@ -29,7 +29,6 @@ tracing-subscriber = { workspace = true, optional = true, features = [ "time", "tracing-log", ] } -tracing-test = { workspace = true, optional = true } [features] default = ["std"] @@ -39,6 +38,5 @@ std = [ "tracing-core/std", "tracing-subscriber", "tracing/std", - "tracing-test", "with-tracing", ] diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 2a48e052c9611..21bba52d07ca0 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -255,6 +255,3 @@ macro_rules! enter_span { $crate::enter_span!($crate::span!($lvl, $name)) }; } - -#[cfg(feature = "std")] -pub use tracing_test; From ca1da9b3b0cfbf563c751ea0559f1fced2c6115f Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 14:38:03 +0000 Subject: [PATCH 10/24] Move LogCapture to sp_tracing --- polkadot/xcm/xcm-simulator/example/src/lib.rs | 87 +----------------- .../xcm/xcm-simulator/example/src/tests.rs | 4 +- substrate/primitives/tracing/src/lib.rs | 3 + .../tracing/src/log_capture_test.rs | 92 +++++++++++++++++++ 4 files changed, 98 insertions(+), 88 deletions(-) create mode 100644 substrate/primitives/tracing/src/log_capture_test.rs diff --git a/polkadot/xcm/xcm-simulator/example/src/lib.rs b/polkadot/xcm/xcm-simulator/example/src/lib.rs index a9b849c8c9c9b..ac519c2390e94 100644 --- a/polkadot/xcm/xcm-simulator/example/src/lib.rs +++ b/polkadot/xcm/xcm-simulator/example/src/lib.rs @@ -22,10 +22,7 @@ mod tests; use sp_runtime::BuildStorage; use sp_tracing::{self, tracing_subscriber}; -use std::{ - io::Write, - sync::{Arc, Mutex}, -}; +use std::io::Write; use tracing_subscriber::fmt::MakeWriter; use xcm::prelude::*; use xcm_executor::traits::ConvertLocation; @@ -34,88 +31,6 @@ use xcm_simulator::{decl_test_network, decl_test_parachain, decl_test_relay_chai pub const ALICE: sp_runtime::AccountId32 = sp_runtime::AccountId32::new([1u8; 32]); pub const INITIAL_BALANCE: u128 = 1_000_000_000; -/// A reusable log capturing struct for unit tests. -/// Captures logs written during test execution for assertions. -pub struct LogCapture { - buffer: Arc>>, -} - -impl LogCapture { - /// Creates a new `LogCapture` instance with an internal buffer. - pub fn new() -> Self { - LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) } - } - - /// Retrieves the captured logs as a `String`. - 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 { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - let mut logs = self.buffer.lock().unwrap(); - logs.extend_from_slice(buf); - Ok(buf.len()) - } - - 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() - } -} - -/// Runs a test block with logging enabled and captures logs for assertions. -/// Usage: -/// ```ignore -/// let log_capture = run_with_logging!({ -/// my_test_function(); -/// }); -/// assert_logs_contain!(log_capture, "Expected log message"); -/// ``` -#[macro_export] -macro_rules! run_with_logging { - ($test:block) => {{ - let log_capture = LogCapture::new(); - let subscriber = tracing_subscriber::fmt().with_writer(log_capture.writer()).finish(); - - tracing::subscriber::with_default(subscriber, || $test); - - log_capture - }}; -} - -/// Macro to assert that captured logs contain a specific substring. -/// Usage: -/// ```ignore -/// assert_logs_contain!(log_capture, "Expected log message"); -/// ``` -#[macro_export] -macro_rules! assert_logs_contain { - ($log_capture:expr, $expected:expr) => { - let logs = $log_capture.get_logs(); - assert!( - logs.contains($expected), - "Expected '{}' in logs, but logs were:\n{}", - $expected, - logs - ); - }; -} - decl_test_parachain! { pub struct ParaA { Runtime = parachain::Runtime, diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 2518a3d09e6f5..3f6459121959e 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -514,13 +514,13 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::{tracing, tracing_subscriber}; + use sp_tracing::{assert_logs_contain, capturing_logs, tracing, tracing_subscriber}; // Reset the test network MockNet::reset(); // Execute XCM Transfer and Capture Logs - let log_capture = run_with_logging!({ + let log_capture = capturing_logs!({ Relay::execute_with(|| { let invalid_dest = Box::new(Parachain(9999).into()); let result = RelayChainPalletXcm::limited_reserve_transfer_assets( diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 21bba52d07ca0..72de481624274 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -255,3 +255,6 @@ macro_rules! enter_span { $crate::enter_span!($crate::span!($lvl, $name)) }; } + +#[cfg(feature = "std")] +pub mod log_capture_test; diff --git a/substrate/primitives/tracing/src/log_capture_test.rs b/substrate/primitives/tracing/src/log_capture_test.rs new file mode 100644 index 0000000000000..253a3d36e3c26 --- /dev/null +++ b/substrate/primitives/tracing/src/log_capture_test.rs @@ -0,0 +1,92 @@ +use std::{ + io::Write, + sync::{Arc, Mutex}, +}; +use tracing_subscriber::fmt::MakeWriter; + +/// A reusable log capturing struct for unit tests. +/// Captures logs written during test execution for assertions. +pub struct LogCapture { + buffer: Arc>>, +} + +impl LogCapture { + /// Creates a new `LogCapture` instance with an internal buffer. + pub fn new() -> Self { + LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) } + } + + /// Retrieves the captured logs as a `String`. + 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 { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let mut logs = self.buffer.lock().unwrap(); + logs.extend_from_slice(buf); + Ok(buf.len()) + } + + 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() + } +} + +/// Runs a test block with logging enabled and captures logs for assertions. +/// Usage: +/// ``` +/// use sp_tracing::{assert_logs_contain, capturing_logs}; +/// #[test] +/// fn test_logging_capture() { +/// let log_capture = capturing_logs!({ +/// tracing::info!("Test log message"); +/// }); +/// +/// assert_logs_contain!(log_capture, "Test log message"); +/// } +/// ``` +#[macro_export] +macro_rules! capturing_logs { + ($test:block) => {{ + let log_capture = $crate::log_capture_test::LogCapture::new(); + let subscriber = tracing_subscriber::fmt().with_writer(log_capture.writer()).finish(); + + tracing::subscriber::with_default(subscriber, || $test); + + log_capture + }}; +} + +/// Macro to assert that captured logs contain a specific substring. +/// Usage: +/// ```ignore +/// assert_logs_contain!(log_capture, "Expected log message"); +/// ``` +#[macro_export] +macro_rules! assert_logs_contain { + ($log_capture:expr, $expected:expr) => { + let logs = $log_capture.get_logs(); + assert!( + logs.contains($expected), + "Expected '{}' in logs, but logs were:\n{}", + $expected, + logs + ); + }; +} From 1e82b9e80dbc373bf6c8faae42e8f491f1194bda Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 14:44:37 +0000 Subject: [PATCH 11/24] Remove unused imports --- polkadot/xcm/xcm-simulator/example/src/lib.rs | 3 --- polkadot/xcm/xcm-simulator/example/src/tests.rs | 4 +++- 2 files changed, 3 insertions(+), 4 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/lib.rs b/polkadot/xcm/xcm-simulator/example/src/lib.rs index ac519c2390e94..16bf564d8d1e1 100644 --- a/polkadot/xcm/xcm-simulator/example/src/lib.rs +++ b/polkadot/xcm/xcm-simulator/example/src/lib.rs @@ -21,9 +21,6 @@ mod relay_chain; mod tests; use sp_runtime::BuildStorage; -use sp_tracing::{self, tracing_subscriber}; -use std::io::Write; -use tracing_subscriber::fmt::MakeWriter; use xcm::prelude::*; use xcm_executor::traits::ConvertLocation; use xcm_simulator::{decl_test_network, decl_test_parachain, decl_test_relay_chain, TestExt}; diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 3f6459121959e..67fcf9fb3d398 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -514,7 +514,9 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::{assert_logs_contain, capturing_logs, tracing, tracing_subscriber}; + use sp_tracing::{ + assert_logs_contain, capturing_logs, tracing, tracing_subscriber, + }; // Reset the test network MockNet::reset(); From bcb56d5865a098be6692fa5c591dba6c61a3209b Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 14:48:26 +0000 Subject: [PATCH 12/24] Add use sp_tracing back --- polkadot/xcm/xcm-simulator/example/src/lib.rs | 1 + polkadot/xcm/xcm-simulator/example/src/tests.rs | 4 +--- 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/lib.rs b/polkadot/xcm/xcm-simulator/example/src/lib.rs index 16bf564d8d1e1..8a05569831b5c 100644 --- a/polkadot/xcm/xcm-simulator/example/src/lib.rs +++ b/polkadot/xcm/xcm-simulator/example/src/lib.rs @@ -21,6 +21,7 @@ mod relay_chain; mod tests; use sp_runtime::BuildStorage; +use sp_tracing; use xcm::prelude::*; use xcm_executor::traits::ConvertLocation; use xcm_simulator::{decl_test_network, decl_test_parachain, decl_test_relay_chain, TestExt}; diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 67fcf9fb3d398..3f6459121959e 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -514,9 +514,7 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::{ - assert_logs_contain, capturing_logs, tracing, tracing_subscriber, - }; + use sp_tracing::{assert_logs_contain, capturing_logs, tracing, tracing_subscriber}; // Reset the test network MockNet::reset(); From 617fcede2c119aec41e0c4bac1bc1b55a962bb16 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 16:21:22 +0000 Subject: [PATCH 13/24] Simplify log capture --- Cargo.lock | 22 +++++ Cargo.toml | 1 + .../xcm/xcm-simulator/example/src/tests.rs | 7 +- substrate/primitives/tracing/Cargo.toml | 2 + substrate/primitives/tracing/src/lib.rs | 19 +++- .../tracing/src/log_capture_test.rs | 92 ------------------- 6 files changed, 47 insertions(+), 96 deletions(-) delete mode 100644 substrate/primitives/tracing/src/log_capture_test.rs diff --git a/Cargo.lock b/Cargo.lock index c6fefcfdfe186..5d4345432abea 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -27808,6 +27808,7 @@ dependencies = [ "tracing", "tracing-core", "tracing-subscriber 0.3.18", + "tracing-test", ] [[package]] @@ -30433,6 +30434,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 0769a95932d44..83c9824fc7182 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 3f6459121959e..bb332eb0d6d8b 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -18,6 +18,7 @@ use crate::*; use codec::Encode; use frame_support::{assert_ok, weights::Weight}; +use sp_tracing::tracing::Subscriber; use xcm::latest::QueryResponseInfo; use xcm_simulator::{mock_message_queue::ReceivedDmp, TestExt}; @@ -514,13 +515,13 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::{assert_logs_contain, capturing_logs, tracing, tracing_subscriber}; + use sp_tracing::log_capture; // Reset the test network MockNet::reset(); // Execute XCM Transfer and Capture Logs - let log_capture = capturing_logs!({ + log_capture::capture(|| { Relay::execute_with(|| { let invalid_dest = Box::new(Parachain(9999).into()); let result = RelayChainPalletXcm::limited_reserve_transfer_assets( @@ -546,5 +547,5 @@ fn reserve_transfer_with_error() { }); // Assertions on Captured Logs - assert_logs_contain!(log_capture, "XCM validate_send failed"); + assert!(log_capture::logs_contain("XCM validate_send failed")); } diff --git a/substrate/primitives/tracing/Cargo.toml b/substrate/primitives/tracing/Cargo.toml index 8621582c76547..f07818cba73e5 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"] @@ -38,5 +39,6 @@ std = [ "tracing-core/std", "tracing-subscriber", "tracing/std", + "tracing-test", "with-tracing", ] diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 72de481624274..420151dbdd4a6 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -257,4 +257,21 @@ macro_rules! enter_span { } #[cfg(feature = "std")] -pub mod log_capture_test; +pub use tracing_test; + +#[cfg(feature = "std")] +pub mod log_capture { + use tracing::subscriber; + use tracing_test::internal::{global_buf, MockWriter}; + + pub fn capture(f: F) { + let log_capture = MockWriter::new(&global_buf()); + let subscriber = tracing_subscriber::fmt().with_writer(log_capture).finish(); + subscriber::with_default(subscriber, f); + } + + pub fn logs_contain(value: &str) -> bool { + let logs = String::from_utf8(global_buf().lock().unwrap().clone()).unwrap(); + logs.contains(value) + } +} diff --git a/substrate/primitives/tracing/src/log_capture_test.rs b/substrate/primitives/tracing/src/log_capture_test.rs deleted file mode 100644 index 253a3d36e3c26..0000000000000 --- a/substrate/primitives/tracing/src/log_capture_test.rs +++ /dev/null @@ -1,92 +0,0 @@ -use std::{ - io::Write, - sync::{Arc, Mutex}, -}; -use tracing_subscriber::fmt::MakeWriter; - -/// A reusable log capturing struct for unit tests. -/// Captures logs written during test execution for assertions. -pub struct LogCapture { - buffer: Arc>>, -} - -impl LogCapture { - /// Creates a new `LogCapture` instance with an internal buffer. - pub fn new() -> Self { - LogCapture { buffer: Arc::new(Mutex::new(Vec::new())) } - } - - /// Retrieves the captured logs as a `String`. - 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 { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - let mut logs = self.buffer.lock().unwrap(); - logs.extend_from_slice(buf); - Ok(buf.len()) - } - - 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() - } -} - -/// Runs a test block with logging enabled and captures logs for assertions. -/// Usage: -/// ``` -/// use sp_tracing::{assert_logs_contain, capturing_logs}; -/// #[test] -/// fn test_logging_capture() { -/// let log_capture = capturing_logs!({ -/// tracing::info!("Test log message"); -/// }); -/// -/// assert_logs_contain!(log_capture, "Test log message"); -/// } -/// ``` -#[macro_export] -macro_rules! capturing_logs { - ($test:block) => {{ - let log_capture = $crate::log_capture_test::LogCapture::new(); - let subscriber = tracing_subscriber::fmt().with_writer(log_capture.writer()).finish(); - - tracing::subscriber::with_default(subscriber, || $test); - - log_capture - }}; -} - -/// Macro to assert that captured logs contain a specific substring. -/// Usage: -/// ```ignore -/// assert_logs_contain!(log_capture, "Expected log message"); -/// ``` -#[macro_export] -macro_rules! assert_logs_contain { - ($log_capture:expr, $expected:expr) => { - let logs = $log_capture.get_logs(); - assert!( - logs.contains($expected), - "Expected '{}' in logs, but logs were:\n{}", - $expected, - logs - ); - }; -} From 4a37d17914ee22600d5b594194a36444923e62dd Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 16:24:29 +0000 Subject: [PATCH 14/24] Remove unused imports --- polkadot/xcm/xcm-simulator/example/src/tests.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index bb332eb0d6d8b..6471428efa828 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -18,7 +18,6 @@ use crate::*; use codec::Encode; use frame_support::{assert_ok, weights::Weight}; -use sp_tracing::tracing::Subscriber; use xcm::latest::QueryResponseInfo; use xcm_simulator::{mock_message_queue::ReceivedDmp, TestExt}; From 7dd08466676b2bbaeec83ea0afaa4675ad7d408e Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Wed, 19 Feb 2025 16:26:11 +0000 Subject: [PATCH 15/24] Add doc tests --- substrate/primitives/tracing/src/lib.rs | 48 +++++++++++++++++++++++++ 1 file changed, 48 insertions(+) diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 420151dbdd4a6..464da84443f3f 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -259,17 +259,65 @@ macro_rules! enter_span { #[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::log_capture; +/// +/// log_capture::capture(|| { +/// tracing::info!("This is a test log message"); +/// }); +/// +/// assert!(log_capture::logs_contain("test log message")); +/// ``` #[cfg(feature = "std")] pub mod log_capture { use tracing::subscriber; 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::log_capture; + /// + /// log_capture::capture(|| { + /// tracing::warn!("Captured warning message"); + /// }); + /// + /// assert!(log_capture::logs_contain("Captured warning message")); + /// ``` pub fn capture(f: F) { let log_capture = MockWriter::new(&global_buf()); let subscriber = tracing_subscriber::fmt().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::log_capture; + /// + /// log_capture::capture(|| { + /// tracing::debug!("Debug log for testing"); + /// }); + /// + /// assert!(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) From 4ff842fc1a0342c8d6023d10a82df38aa2301dea Mon Sep 17 00:00:00 2001 From: "cmd[bot]" <41898282+github-actions[bot]@users.noreply.github.com> Date: Thu, 20 Feb 2025 09:36:22 +0000 Subject: [PATCH 16/24] Update from raymondkfcheung running command 'prdoc --audience runtime_dev --bump patch' --- prdoc/pr_7594.prdoc | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) create mode 100644 prdoc/pr_7594.prdoc diff --git a/prdoc/pr_7594.prdoc b/prdoc/pr_7594.prdoc new file mode 100644 index 0000000000000..0133785fb63bb --- /dev/null +++ b/prdoc/pr_7594.prdoc @@ -0,0 +1,25 @@ +title: Improve XCM Debugging by Capturing Logs in Unit Tests +doc: +- audience: Runtime Dev + description: |- + # Description + + This PR introduces a lightweight log-capturing mechanism for XCM unit tests, making it easier to troubleshoot failures when needed. It partially addresses #6119 and #6125 by providing an optional way to verify log outputs in tests. + + # TODOs + + * [ ] Introduces a structured way to capture logs for XCM debugging. + * [ ] Ensures logging remains unobtrusive in passing tests but is available when debugging. + + # Review Notes: + + * This PR does not enforce logging in all tests but provides a reusable mechanism for capturing logs when necessary. + * The implementation is minimal and does not add complexity to existing test setups. + * Developers can still rely on standard logging, [`sp_tracing::init_for_tests()`](https://paritytech.github.io/polkadot-sdk/master/sp_tracing/fn.init_for_tests.html), when manual debugging is sufficient. +crates: +- name: pallet-xcm + bump: patch +- name: xcm-simulator-example + bump: patch +- name: sp-tracing + bump: patch From 24c09af9a7b81059754659e3d4aa54486bccf3e0 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Thu, 20 Feb 2025 09:56:08 +0000 Subject: [PATCH 17/24] Rename to test_log_capture --- .../xcm/xcm-simulator/example/src/tests.rs | 6 ++-- substrate/primitives/tracing/src/lib.rs | 30 ++++++++++++------- 2 files changed, 22 insertions(+), 14 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 6471428efa828..fe0a86f4d757c 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -514,13 +514,13 @@ fn query_holding() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::log_capture; + use sp_tracing::test_log_capture; // Reset the test network MockNet::reset(); // Execute XCM Transfer and Capture Logs - log_capture::capture(|| { + test_log_capture::capture(|| { Relay::execute_with(|| { let invalid_dest = Box::new(Parachain(9999).into()); let result = RelayChainPalletXcm::limited_reserve_transfer_assets( @@ -546,5 +546,5 @@ fn reserve_transfer_with_error() { }); // Assertions on Captured Logs - assert!(log_capture::logs_contain("XCM validate_send failed")); + assert!(test_log_capture::logs_contain("XCM validate_send failed")); } diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index 464da84443f3f..f6dcecee84d2b 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -267,17 +267,18 @@ pub use tracing_test; /// # Example /// /// ``` -/// use sp_tracing::log_capture; +/// use sp_tracing::test_log_capture; /// -/// log_capture::capture(|| { +/// test_log_capture::capture(|| { /// tracing::info!("This is a test log message"); /// }); /// -/// assert!(log_capture::logs_contain("test log message")); +/// assert!(test_log_capture::logs_contain("test log message")); /// ``` #[cfg(feature = "std")] -pub mod log_capture { +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. @@ -288,17 +289,24 @@ pub mod log_capture { /// # Example /// /// ``` - /// use sp_tracing::log_capture; + /// use sp_tracing::test_log_capture; /// - /// log_capture::capture(|| { + /// test_log_capture::capture(|| { /// tracing::warn!("Captured warning message"); /// }); /// - /// assert!(log_capture::logs_contain("Captured warning message")); + /// assert!(test_log_capture::logs_contain("Captured warning message")); /// ``` pub fn capture(f: F) { + capture_with_max_level(LevelFilter::TRACE, f); + } + + 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_writer(log_capture).finish(); + let subscriber = tracing_subscriber::fmt() + .with_max_level(max_level) + .with_writer(log_capture) + .finish(); subscriber::with_default(subscriber, f); } @@ -310,13 +318,13 @@ pub mod log_capture { /// # Example /// /// ``` - /// use sp_tracing::log_capture; + /// use sp_tracing::test_log_capture; /// - /// log_capture::capture(|| { + /// test_log_capture::capture(|| { /// tracing::debug!("Debug log for testing"); /// }); /// - /// assert!(log_capture::logs_contain("Debug log")); + /// 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(); From c5c4050899daaa2b30904e2011ca8264db730e07 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Thu, 20 Feb 2025 10:06:40 +0000 Subject: [PATCH 18/24] Update docs --- substrate/primitives/tracing/src/lib.rs | 34 +++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index f6dcecee84d2b..a0c2bdb8001f1 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -256,6 +256,23 @@ macro_rules! enter_span { }; } +/// `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; @@ -301,6 +318,23 @@ pub mod test_log_capture { capture_with_max_level(LevelFilter::TRACE, 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() From e8c40c09ced240df0007f5e3ee484f703646c795 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Thu, 20 Feb 2025 10:43:32 +0000 Subject: [PATCH 19/24] Update tests --- .../xcm/xcm-simulator/example/src/tests.rs | 101 +++++++++++------- 1 file changed, 63 insertions(+), 38 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index fe0a86f4d757c..82371dc57cdb6 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -136,6 +136,16 @@ 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 +157,58 @@ fn reserve_transfer() { }); } +#[test] +fn reserve_transfer_with_error() { + use sp_tracing::test_log_capture; + + // Reset the test network + MockNet::reset(); + + // Execute XCM Transfer and Capture Logs + test_log_capture::capture(|| { + 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 + ); + + let events = parachain::System::events(); + println!("{:?}", events); + }); + }); + + // Assertions on Captured Logs + assert!(test_log_capture::logs_contain("XCM validate_send failed")); +} + #[test] fn remote_locking_and_unlocking() { MockNet::reset(); @@ -510,41 +572,4 @@ fn query_holding() { }])], ); }); -} - -#[test] -fn reserve_transfer_with_error() { - use sp_tracing::test_log_capture; - - // Reset the test network - MockNet::reset(); - - // Execute XCM Transfer and Capture Logs - test_log_capture::capture(|| { - Relay::execute_with(|| { - let invalid_dest = Box::new(Parachain(9999).into()); - 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, 123u128).into()), - 0, - Unlimited, - ); - - // Ensure an error occurred - assert!(result.is_err(), "Expected an error due to invalid destination"); - }); - - // 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")); -} +} \ No newline at end of file From ab31f4b95bdb797d58fe1af6f3795e45a330ca15 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Thu, 20 Feb 2025 10:45:34 +0000 Subject: [PATCH 20/24] Update PR doc --- .../xcm/xcm-simulator/example/src/tests.rs | 35 +++++++++++++------ prdoc/pr_7594.prdoc | 15 +------- 2 files changed, 26 insertions(+), 24 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 82371dc57cdb6..5ae1e9b39a799 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -138,12 +138,24 @@ fn reserve_transfer() { ); // 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(); + 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"); }); @@ -184,9 +196,12 @@ fn reserve_transfer_with_error() { // 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 { .. })) - ); + 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" @@ -572,4 +587,4 @@ fn query_holding() { }])], ); }); -} \ No newline at end of file +} diff --git a/prdoc/pr_7594.prdoc b/prdoc/pr_7594.prdoc index 0133785fb63bb..f289816b884ca 100644 --- a/prdoc/pr_7594.prdoc +++ b/prdoc/pr_7594.prdoc @@ -2,20 +2,7 @@ title: Improve XCM Debugging by Capturing Logs in Unit Tests doc: - audience: Runtime Dev description: |- - # Description - - This PR introduces a lightweight log-capturing mechanism for XCM unit tests, making it easier to troubleshoot failures when needed. It partially addresses #6119 and #6125 by providing an optional way to verify log outputs in tests. - - # TODOs - - * [ ] Introduces a structured way to capture logs for XCM debugging. - * [ ] Ensures logging remains unobtrusive in passing tests but is available when debugging. - - # Review Notes: - - * This PR does not enforce logging in all tests but provides a reusable mechanism for capturing logs when necessary. - * The implementation is minimal and does not add complexity to existing test setups. - * Developers can still rely on standard logging, [`sp_tracing::init_for_tests()`](https://paritytech.github.io/polkadot-sdk/master/sp_tracing/fn.init_for_tests.html), when manual debugging is sufficient. + 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 From f0d0d56d704afc56a27e69909bdf4de69f00893a Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Thu, 20 Feb 2025 10:46:19 +0000 Subject: [PATCH 21/24] Update tests --- polkadot/xcm/xcm-simulator/example/src/tests.rs | 3 --- 1 file changed, 3 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 5ae1e9b39a799..239b152d8ca14 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -214,9 +214,6 @@ fn reserve_transfer_with_error() { pallet_balances::Pallet::::free_balance(&ALICE), INITIAL_BALANCE ); - - let events = parachain::System::events(); - println!("{:?}", events); }); }); From fed17470d2d155c6c56b412fdaec401eff407a10 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Thu, 20 Feb 2025 11:04:55 +0000 Subject: [PATCH 22/24] Change default max_level to DEBUG --- polkadot/xcm/xcm-simulator/example/src/tests.rs | 4 ++-- substrate/primitives/tracing/src/lib.rs | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/polkadot/xcm/xcm-simulator/example/src/tests.rs b/polkadot/xcm/xcm-simulator/example/src/tests.rs index 239b152d8ca14..8937fcc03fffc 100644 --- a/polkadot/xcm/xcm-simulator/example/src/tests.rs +++ b/polkadot/xcm/xcm-simulator/example/src/tests.rs @@ -171,13 +171,13 @@ fn reserve_transfer() { #[test] fn reserve_transfer_with_error() { - use sp_tracing::test_log_capture; + use sp_tracing::{test_log_capture, tracing::Level}; // Reset the test network MockNet::reset(); // Execute XCM Transfer and Capture Logs - test_log_capture::capture(|| { + test_log_capture::capture_with_max_level(Level::ERROR, || { let invalid_dest = Box::new(Parachain(9999).into()); let withdraw_amount = 123; diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index a0c2bdb8001f1..e51e14e6df439 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/substrate/primitives/tracing/src/lib.rs @@ -315,7 +315,7 @@ pub mod test_log_capture { /// assert!(test_log_capture::logs_contain("Captured warning message")); /// ``` pub fn capture(f: F) { - capture_with_max_level(LevelFilter::TRACE, f); + capture_with_max_level(LevelFilter::DEBUG, f); } /// Runs a test block with logging enabled and captures logs for assertions From e7094199ebbbeda89c88880bc8a2a822d3661092 Mon Sep 17 00:00:00 2001 From: "cmd[bot]" <41898282+github-actions[bot]@users.noreply.github.com> Date: Fri, 21 Feb 2025 11:44:42 +0000 Subject: [PATCH 23/24] Update from raymondkfcheung running command 'fmt' --- substrate/primitives/tracing/Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/substrate/primitives/tracing/Cargo.toml b/substrate/primitives/tracing/Cargo.toml index f07818cba73e5..a874514b59062 100644 --- a/substrate/primitives/tracing/Cargo.toml +++ b/substrate/primitives/tracing/Cargo.toml @@ -38,7 +38,7 @@ std = [ "codec/std", "tracing-core/std", "tracing-subscriber", - "tracing/std", "tracing-test", + "tracing/std", "with-tracing", ] From 2411944f0b6857907f44d58c270211ec8dd12050 Mon Sep 17 00:00:00 2001 From: Raymond Cheung <178801527+raymondkfcheung@users.noreply.github.com> Date: Fri, 21 Feb 2025 12:06:36 +0000 Subject: [PATCH 24/24] Update PR doc --- prdoc/pr_7594.prdoc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/prdoc/pr_7594.prdoc b/prdoc/pr_7594.prdoc index f289816b884ca..d79fc34ecdec9 100644 --- a/prdoc/pr_7594.prdoc +++ b/prdoc/pr_7594.prdoc @@ -9,4 +9,4 @@ crates: - name: xcm-simulator-example bump: patch - name: sp-tracing - bump: patch + bump: minor