From aeb0ca0d73d4d3692b432dcc17a921ed5bcf6805 Mon Sep 17 00:00:00 2001 From: Ignacio Duart Date: Mon, 27 Oct 2025 19:45:08 +0100 Subject: [PATCH] fix(tests): prevent span accumulation across async tasks MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fix span accumulation issue in multi-peer tests where tracing spans were being inherited and accumulated across async task boundaries, making it impossible to determine which peer a log entry belonged to. ## Changes ### Pattern Applied Replace `with_peer_id()` calls inside async blocks with `.instrument()` to attach isolated spans: **Before (broken):** ```rust let node = async { let _span = with_peer_id("gateway"); // ... }.boxed_local(); ``` **After (fixed):** ```rust let node = async { // ... } .instrument(tracing::info_span!("test_peer", test_node = "gateway")) .boxed_local(); ``` ### Files Modified - operations.rs: Fixed 3 tests (test_put_contract, test_put_merge_persists_state, test_multiple_clients_subscription) - connectivity.rs: Fixed all tests with multi-peer scenarios - test_utils.rs: Removed with_peer_id() function that caused the issue ## Result Each peer now has isolated spans in logs: - "spans":[{"test_node":"gateway"}] - Gateway logs only - "spans":[{"test_node":"peer-1"}] - Peer-1 logs only This significantly improves debugging experience for multi-peer tests. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude --- crates/core/src/test_utils.rs | 75 ++++++------------------------- crates/core/tests/connectivity.rs | 15 ++++--- crates/core/tests/operations.rs | 16 +++---- 3 files changed, 29 insertions(+), 77 deletions(-) diff --git a/crates/core/src/test_utils.rs b/crates/core/src/test_utils.rs index d3bee98b2..98f3b67a8 100644 --- a/crates/core/src/test_utils.rs +++ b/crates/core/src/test_utils.rs @@ -42,59 +42,6 @@ pub fn set_peer_id(peer_id: impl Into) { tracing::Span::current().record("test_node", peer_id); } -/// Create a span with a peer identifier that will be included in all logs -/// within the span. -/// -/// # Example -/// ```ignore -/// async fn start_gateway() { -/// let _span = with_peer_id("gateway"); -/// tracing::info!("Starting gateway"); // Will include test_node="gateway" -/// // ... gateway initialization -/// } -/// -/// async fn start_peer(id: usize) { -/// let _span = with_peer_id(format!("peer-{}", id)); -/// tracing::info!("Starting peer"); // Will include test_node="peer-N" -/// // ... peer initialization -/// } -/// ``` -/// -/// # Note -/// The field name `test_node` is used to avoid conflicts with the production -/// `peer` field which contains the actual cryptographic PeerId. -/// -/// # Important -/// The returned guard must be held for the entire duration you want the peer ID -/// to be active. When the guard is dropped, the span exits. -#[must_use = "Span guard must be held for the duration of the operation"] -pub fn with_peer_id(peer_id: impl Into) -> impl Drop { - let peer_id = peer_id.into(); - tracing::info_span!("test_peer", test_node = %peer_id).entered() -} - -/// Execute a function with tracing enabled. -/// -/// This function is now deprecated in favor of using the `#[test_log::test]` macro -/// which provides better integration with test frameworks and only shows logs for -/// failing tests. -/// -/// # Deprecated -/// Use `#[test_log::test]` or `#[test_log::test(tokio::test)]` instead. -#[deprecated( - since = "0.1.0", - note = "Use #[test_log::test] or #[test_log::test(tokio::test)] instead" -)] -pub fn with_tracing(f: impl FnOnce() -> T) -> T { - let subscriber = tracing_subscriber::fmt() - .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) - .with_line_number(true) - .with_file(true) - .with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE) - .finish(); - tracing::subscriber::with_default(subscriber, f) -} - /// Format for test logger output #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub enum LogFormat { @@ -113,16 +60,20 @@ pub enum LogFormat { /// /// # Peer Identification /// -/// For multi-peer tests, use the `with_peer_id()` function in each async block: +/// For multi-peer tests, use `.instrument()` to attach isolated spans: /// ```ignore +/// use tracing::Instrument; +/// /// let gateway = async { -/// let _span = with_peer_id("gateway"); /// tracing::info!("Gateway starting"); -/// }; +/// } +/// .instrument(tracing::info_span!("test_peer", test_node = "gateway")); /// ``` /// /// # Example /// ```ignore +/// use tracing::Instrument; +/// /// #[tokio::test] /// async fn my_test() -> anyhow::Result<()> { /// let _logger = TestLogger::new() @@ -130,11 +81,11 @@ pub enum LogFormat { /// .with_level("debug") /// .init(); /// -/// // For multi-peer tests, use with_peer_id() in each async block +/// // For multi-peer tests, use .instrument() to isolate spans /// let gateway = async { -/// let _span = with_peer_id("gateway"); /// tracing::info!("Gateway starting"); -/// }; +/// } +/// .instrument(tracing::info_span!("test_peer", test_node = "gateway")); /// /// Ok(()) /// } @@ -778,7 +729,7 @@ mod test { fn test_logger_with_peer_id() { let _logger = TestLogger::new().with_level("info").init(); - let _span = with_peer_id("test-peer"); + let _span = tracing::info_span!("test_peer", test_node = "test-peer").entered(); tracing::info!("Message with peer ID"); } @@ -820,7 +771,7 @@ mod test { async fn test_logger_async() { let _logger = TestLogger::new().with_json().with_level("debug").init(); - let _span = with_peer_id("async-peer"); + let _span = tracing::info_span!("test_peer", test_node = "async-peer").entered(); tracing::info!("Async test message"); tokio::time::sleep(tokio::time::Duration::from_millis(10)).await; @@ -836,7 +787,7 @@ mod test { .init(); // Create a span with test_node field - let _span = with_peer_id("test-gateway"); + let _span = tracing::info_span!("test_peer", test_node = "test-gateway").entered(); tracing::info!("Message from gateway"); diff --git a/crates/core/tests/connectivity.rs b/crates/core/tests/connectivity.rs index e472da7fe..d4798445d 100644 --- a/crates/core/tests/connectivity.rs +++ b/crates/core/tests/connectivity.rs @@ -4,7 +4,7 @@ use freenet::{ dev_tool::TransportKeypair, local_node::NodeConfig, server::serve_gateway, - test_utils::{self, make_get, make_put, with_peer_id}, + test_utils::{self, make_get, make_put}, }; use freenet_stdlib::{ client_api::{ClientRequest, ContractResponse, HostResponse, WebApi}, @@ -20,6 +20,7 @@ use std::{ use testresult::TestResult; use tokio::select; use tokio_tungstenite::connect_async; +use tracing::Instrument; static RNG: LazyLock> = LazyLock::new(|| { Mutex::new(rand::rngs::StdRng::from_seed( @@ -144,7 +145,6 @@ async fn test_gateway_reconnection() -> TestResult { // Start gateway node with peer identification let gateway = async { - let _span = with_peer_id("gateway"); tracing::info!("Starting gateway node"); let config = gateway_config.build().await?; let node = NodeConfig::new(config.clone()) @@ -154,11 +154,11 @@ async fn test_gateway_reconnection() -> TestResult { tracing::info!("Gateway node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "gateway")) .boxed_local(); // Start peer node with peer identification let peer = async move { - let _span = with_peer_id("peer-1"); tracing::info!("Starting peer node"); let config = peer_config.build().await?; let node = NodeConfig::new(config.clone()) @@ -168,6 +168,7 @@ async fn test_gateway_reconnection() -> TestResult { tracing::info!("Peer node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "peer-1")) .boxed_local(); // Main test logic @@ -374,7 +375,6 @@ async fn test_basic_gateway_connectivity() -> TestResult { // Start the gateway node with peer identification let gateway = async { - let _span = with_peer_id("gateway"); tracing::info!("Starting gateway node"); let config = config.build().await?; let node = NodeConfig::new(config.clone()) @@ -384,6 +384,7 @@ async fn test_basic_gateway_connectivity() -> TestResult { tracing::info!("Gateway node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "gateway")) .boxed_local(); // Test logic @@ -646,7 +647,6 @@ async fn test_three_node_network_connectivity() -> TestResult { // Start gateway node with peer identification let gateway = async { - let _span = with_peer_id("gateway"); tracing::info!("Starting gateway node"); let config = gateway_config.build().await?; let node = NodeConfig::new(config.clone()) @@ -656,11 +656,11 @@ async fn test_three_node_network_connectivity() -> TestResult { tracing::info!("Gateway node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "gateway")) .boxed_local(); // Start first peer node with peer identification let peer1 = async move { - let _span = with_peer_id("peer-1"); tokio::time::sleep(Duration::from_secs(5)).await; tracing::info!("Starting peer 1 node"); let config = peer1_config.build().await?; @@ -671,11 +671,11 @@ async fn test_three_node_network_connectivity() -> TestResult { tracing::info!("Peer 1 node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "peer-1")) .boxed_local(); // Start second peer node with peer identification let peer2 = async move { - let _span = with_peer_id("peer-2"); tokio::time::sleep(Duration::from_secs(10)).await; tracing::info!("Starting peer 2 node"); let config = peer2_config.build().await?; @@ -686,6 +686,7 @@ async fn test_three_node_network_connectivity() -> TestResult { tracing::info!("Peer 2 node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "peer-2")) .boxed_local(); // Main test logic diff --git a/crates/core/tests/operations.rs b/crates/core/tests/operations.rs index ad3597a64..e8b75fabe 100644 --- a/crates/core/tests/operations.rs +++ b/crates/core/tests/operations.rs @@ -6,7 +6,7 @@ use freenet::{ server::serve_gateway, test_utils::{ self, load_delegate, make_get, make_put, make_subscribe, make_update, - verify_contract_exists, with_peer_id, TestLogger, + verify_contract_exists, TestLogger, }, }; use freenet_stdlib::{ @@ -170,7 +170,6 @@ async fn test_put_contract() -> TestResult { std::mem::drop(ws_api_port_socket_a); // Free the port so it does not fail on initialization let node_a = async move { - let _span = with_peer_id("peer-a"); tracing::info!("Starting peer A node"); let config = config_a.build().await?; let node = NodeConfig::new(config.clone()) @@ -180,12 +179,12 @@ async fn test_put_contract() -> TestResult { tracing::info!("Peer A node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "peer-a")) .boxed_local(); std::mem::drop(network_socket_b); // Free the port so it does not fail on initialization std::mem::drop(ws_api_port_socket_b); let node_b = async { - let _span = with_peer_id("gateway"); tracing::info!("Starting gateway node"); let config = config_b.build().await?; let node = NodeConfig::new(config.clone()) @@ -195,6 +194,7 @@ async fn test_put_contract() -> TestResult { tracing::info!("Gateway node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "gateway")) .boxed_local(); let test = tokio::time::timeout(Duration::from_secs(180), async { @@ -586,7 +586,6 @@ async fn test_put_merge_persists_state() -> TestResult { // Start node A (peer) std::mem::drop(ws_api_port_socket_a); let node_a = async move { - let _span = with_peer_id("peer-a"); tracing::info!("Starting peer A node"); let config = config_a.build().await?; let node = NodeConfig::new(config.clone()) @@ -596,13 +595,13 @@ async fn test_put_merge_persists_state() -> TestResult { tracing::info!("Peer A node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "peer-a")) .boxed_local(); // Start node B (gateway) std::mem::drop(network_socket_b); std::mem::drop(ws_api_port_socket_b); let node_b = async { - let _span = with_peer_id("gateway"); tracing::info!("Starting gateway node"); let config = config_b.build().await?; let node = NodeConfig::new(config.clone()) @@ -612,6 +611,7 @@ async fn test_put_merge_persists_state() -> TestResult { tracing::info!("Gateway node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "gateway")) .boxed_local(); let test = tokio::time::timeout(Duration::from_secs(180), async { @@ -868,7 +868,6 @@ async fn test_multiple_clients_subscription() -> TestResult { // Start node A (first client) let node_a = async move { - let _span = with_peer_id("node-a"); tracing::info!("Starting node A"); let config = config_a.build().await?; let node = NodeConfig::new(config.clone()) @@ -878,11 +877,11 @@ async fn test_multiple_clients_subscription() -> TestResult { tracing::info!("Node A running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "node-a")) .boxed_local(); // Start GW node let node_gw = async { - let _span = with_peer_id("gateway"); tracing::info!("Starting gateway node"); let config = config_gw.build().await?; let node = NodeConfig::new(config.clone()) @@ -892,11 +891,11 @@ async fn test_multiple_clients_subscription() -> TestResult { tracing::info!("Gateway node running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "gateway")) .boxed_local(); // Start node B (second client) let node_b = async { - let _span = with_peer_id("node-b"); tracing::info!("Starting node B"); let config = config_b.build().await?; let node = NodeConfig::new(config.clone()) @@ -906,6 +905,7 @@ async fn test_multiple_clients_subscription() -> TestResult { tracing::info!("Node B running"); node.run().await } + .instrument(tracing::info_span!("test_peer", test_node = "node-b")) .boxed_local(); let test = tokio::time::timeout(Duration::from_secs(600), async {