fix(tests): prevent span accumulation across async tasks (#2007)

Co-authored-by: Claude <noreply@anthropic.com>
Co-authored-by: Ian Clarke <sanity@users.noreply.github.com>

Author: 3 people

crates/core/src/test_utils.rs

@@ -42,59 +42,6 @@ pub fn set_peer_id(peer_id: impl Into<String>) {
     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<String>) -> 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<T>(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,28 +60,32 @@ 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()
 ///         .with_json()
 ///         .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");
 

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<Mutex<rand::rngs::StdRng>> = 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

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 {