From 38305aa1b30bc4bf1a1c871c8dc931e5393f2ab6 Mon Sep 17 00:00:00 2001 From: Floris Bruynooghe Date: Wed, 19 Jul 2023 12:26:22 +0200 Subject: [PATCH 1/3] feat(tests): Provide test-local logging for multi-threaded tests This enables the test-local logging output also for multi-threaded tests. The usage is not as nice as the entire test needs to be wrapped in an async block, but it works. --- Cargo.lock | 1 + iroh-net/Cargo.toml | 1 + iroh-net/src/magicsock.rs | 74 +++++++++++++++++++------------------- iroh-net/src/test_utils.rs | 67 ++++++++++++++++++++++++++++++++-- 4 files changed, 104 insertions(+), 39 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 76bd8d413d..9eb790ce98 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1818,6 +1818,7 @@ dependencies = [ "tokio-util", "toml 0.7.6", "tracing", + "tracing-futures", "tracing-subscriber", "trust-dns-resolver", "ucd-parse", diff --git a/iroh-net/Cargo.toml b/iroh-net/Cargo.toml index 0d03cb04e2..84aad4aa65 100644 --- a/iroh-net/Cargo.toml +++ b/iroh-net/Cargo.toml @@ -89,6 +89,7 @@ ntest = "0.9" pretty_assertions = "1.4" rand_chacha = "0.3.1" tokio = { version = "1", features = ["io-util", "sync", "rt", "net", "fs", "macros", "time", "test-util"] } +tracing-futures = "0.2.5" tracing-subscriber = { version = "0.3", features = ["env-filter"] } [build-dependencies] diff --git a/iroh-net/src/magicsock.rs b/iroh-net/src/magicsock.rs index e42c1fcd9b..7848861fd3 100644 --- a/iroh-net/src/magicsock.rs +++ b/iroh-net/src/magicsock.rs @@ -3085,48 +3085,48 @@ pub(crate) mod tests { #[tokio::test(flavor = "multi_thread")] async fn test_two_devices_setup_teardown() -> Result<()> { - setup_logging(); - - let devices = Devices { - stun_ip: "127.0.0.1".parse()?, - }; - - for _ in 0..10 { - let (derp_map, _, cleanup) = run_derp_and_stun(devices.stun_ip).await?; - println!("setting up magic stack"); - let m1 = MagicStack::new(derp_map.clone()).await?; - let m2 = MagicStack::new(derp_map.clone()).await?; - - let cleanup_mesh = mesh_stacks(vec![m1.clone(), m2.clone()]).await?; + crate::test_utils::with_logging(async move { + let devices = Devices { + stun_ip: "127.0.0.1".parse()?, + }; - // Wait for magicsock to be told about peers from mesh_stacks. - println!("waiting for connection"); - let m1t = m1.clone(); - let m2t = m2.clone(); - time::timeout(Duration::from_secs(10), async move { - loop { - let ab = m1t.tracked_endpoints().await.contains(&m2t.public()); - let ba = m2t.tracked_endpoints().await.contains(&m1t.public()); - if ab && ba { - break; + for _ in 0..10 { + let (derp_map, _, cleanup) = run_derp_and_stun(devices.stun_ip).await?; + println!("setting up magic stack"); + let m1 = MagicStack::new(derp_map.clone()).await?; + let m2 = MagicStack::new(derp_map.clone()).await?; + + let cleanup_mesh = mesh_stacks(vec![m1.clone(), m2.clone()]).await?; + + // Wait for magicsock to be told about peers from mesh_stacks. + println!("waiting for connection"); + let m1t = m1.clone(); + let m2t = m2.clone(); + time::timeout(Duration::from_secs(10), async move { + loop { + let ab = m1t.tracked_endpoints().await.contains(&m2t.public()); + let ba = m2t.tracked_endpoints().await.contains(&m1t.public()); + if ab && ba { + break; + } } - } - }) - .await - .context("failed to connect peers")?; + }) + .await + .context("failed to connect peers")?; - println!("closing endpoints"); - m1.endpoint.close(0u32.into(), b"done").await?; - m2.endpoint.close(0u32.into(), b"done").await?; + println!("closing endpoints"); + m1.endpoint.close(0u32.into(), b"done").await?; + m2.endpoint.close(0u32.into(), b"done").await?; - assert!(m1.endpoint.conn().inner.is_closed()); - assert!(m2.endpoint.conn().inner.is_closed()); + assert!(m1.endpoint.conn().inner.is_closed()); + assert!(m2.endpoint.conn().inner.is_closed()); - println!("cleaning up"); - cleanup().await; - cleanup_mesh(); - } - Ok(()) + println!("cleaning up"); + cleanup().await; + cleanup_mesh(); + } + Ok(()) + }).await } #[tokio::test] diff --git a/iroh-net/src/test_utils.rs b/iroh-net/src/test_utils.rs index 6416b75dc6..be1759d1ef 100644 --- a/iroh-net/src/test_utils.rs +++ b/iroh-net/src/test_utils.rs @@ -1,38 +1,101 @@ //! Internal utilities to support testing. +use std::future::Future; + +use tokio::runtime::RuntimeFlavor; use tracing::level_filters::LevelFilter; +use tracing_futures::WithSubscriber; +use tracing_subscriber::fmt::format::FmtSpan; use tracing_subscriber::layer::{Layer, SubscriberExt}; use tracing_subscriber::util::SubscriberInitExt; use tracing_subscriber::EnvFilter; -/// Configures logging for the current test. +/// Configures logging for the current test, **single-threaded runtime only**. +/// +/// This setup can be used for any sync test or async test using a single-threaded tokio +/// runtime (the default). For multi-threaded runtimes use [`with_logging`]. /// /// This configures logging that will interact well with tests: logs will be captured by the /// test framework and only printed on failure. /// /// The logging is unfiltered, it logs all crates and modules on TRACE level. If that's too /// much consider if your test is too large (or write a version that allows filtering...). +/// +/// # Example +/// +/// ```no_run +/// #[tokio::test] +/// async fn test_something() { +/// let _guard = crate::test_utils::setup_logging(); +/// assert!(true); +/// } #[must_use = "The tracing guard must only be dropped at the end of the test"] #[allow(dead_code)] pub(crate) fn setup_logging() -> tracing::subscriber::DefaultGuard { + if let Ok(handle) = tokio::runtime::Handle::try_current() { + match handle.runtime_flavor() { + RuntimeFlavor::CurrentThread => (), + RuntimeFlavor::MultiThread => { + panic!( + "setup_logging() does not work in a multi-threaded tokio runtime, \ + use with_logging() instead" + ); + } + _ => panic!("unknown runtime flavour"), + } + } + testing_subscriber().set_default() +} + +/// Invoke the future with test logging configured. +/// +/// This can be used to execute any future which uses tracing for logging, it sets up the +/// logging as [`setup_logging`] does but in a way which will work for both single and +/// multi-threaded tokio runtimes. +pub(crate) async fn with_logging(f: F) -> F::Output { + f.with_subscriber(testing_subscriber()).await +} + +/// Returns the a [`tracing::Subscriber`] configured for our tests. +/// +/// This subscriber will ensure that log output is captured by the test's default output +/// capturing and thus is only shown with the test on failure. By default it uses +/// `RUST_LOG=trace` as configuration but you can specify the `RUST_LOG` environment +/// variable explicitly to override this. +/// +/// To use this in a tokio multi-threaded runtime use: +/// +/// ```no_run +/// use tracing_future::WithSubscriber; +/// use crate::test_utils::testing_subscriber; +/// +/// #[tokio::test(flavor = "multi_thread")] +/// async fn test_something() -> Result<()> { +/// async move { +/// Ok(()) +/// }.with_subscriber(testing_subscriber()).await +/// } +/// ``` +pub(crate) fn testing_subscriber() -> impl tracing::Subscriber { let var = std::env::var_os("RUST_LOG"); let trace_log_layer = match var { Some(_) => None, None => Some( tracing_subscriber::fmt::layer() + .with_span_events(FmtSpan::CLOSE) .with_writer(|| TestWriter) .with_filter(LevelFilter::TRACE), ), }; let env_log_layer = var.map(|_| { tracing_subscriber::fmt::layer() + .with_span_events(FmtSpan::CLOSE) .with_writer(|| TestWriter) .with_filter(EnvFilter::from_default_env()) }); tracing_subscriber::registry() .with(trace_log_layer) .with(env_log_layer) - .set_default() } /// A tracing writer that interacts well with test output capture. From daaa449ad41da15443b1a6a59f049b7fb1d2111e Mon Sep 17 00:00:00 2001 From: Floris Bruynooghe Date: Wed, 19 Jul 2023 12:34:49 +0200 Subject: [PATCH 2/3] Revert the with_logging but keep the other improvements --- Cargo.lock | 1 - iroh-net/Cargo.toml | 1 - iroh-net/src/magicsock.rs | 73 +++++++++++++++++++------------------- iroh-net/src/test_utils.rs | 19 +++++----- 4 files changed, 44 insertions(+), 50 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9eb790ce98..76bd8d413d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1818,7 +1818,6 @@ dependencies = [ "tokio-util", "toml 0.7.6", "tracing", - "tracing-futures", "tracing-subscriber", "trust-dns-resolver", "ucd-parse", diff --git a/iroh-net/Cargo.toml b/iroh-net/Cargo.toml index 84aad4aa65..0d03cb04e2 100644 --- a/iroh-net/Cargo.toml +++ b/iroh-net/Cargo.toml @@ -89,7 +89,6 @@ ntest = "0.9" pretty_assertions = "1.4" rand_chacha = "0.3.1" tokio = { version = "1", features = ["io-util", "sync", "rt", "net", "fs", "macros", "time", "test-util"] } -tracing-futures = "0.2.5" tracing-subscriber = { version = "0.3", features = ["env-filter"] } [build-dependencies] diff --git a/iroh-net/src/magicsock.rs b/iroh-net/src/magicsock.rs index 7848861fd3..6fac8235e2 100644 --- a/iroh-net/src/magicsock.rs +++ b/iroh-net/src/magicsock.rs @@ -3085,48 +3085,47 @@ pub(crate) mod tests { #[tokio::test(flavor = "multi_thread")] async fn test_two_devices_setup_teardown() -> Result<()> { - crate::test_utils::with_logging(async move { - let devices = Devices { - stun_ip: "127.0.0.1".parse()?, - }; + setup_logging(); + let devices = Devices { + stun_ip: "127.0.0.1".parse()?, + }; - for _ in 0..10 { - let (derp_map, _, cleanup) = run_derp_and_stun(devices.stun_ip).await?; - println!("setting up magic stack"); - let m1 = MagicStack::new(derp_map.clone()).await?; - let m2 = MagicStack::new(derp_map.clone()).await?; - - let cleanup_mesh = mesh_stacks(vec![m1.clone(), m2.clone()]).await?; - - // Wait for magicsock to be told about peers from mesh_stacks. - println!("waiting for connection"); - let m1t = m1.clone(); - let m2t = m2.clone(); - time::timeout(Duration::from_secs(10), async move { - loop { - let ab = m1t.tracked_endpoints().await.contains(&m2t.public()); - let ba = m2t.tracked_endpoints().await.contains(&m1t.public()); - if ab && ba { - break; - } + for _ in 0..10 { + let (derp_map, _, cleanup) = run_derp_and_stun(devices.stun_ip).await?; + println!("setting up magic stack"); + let m1 = MagicStack::new(derp_map.clone()).await?; + let m2 = MagicStack::new(derp_map.clone()).await?; + + let cleanup_mesh = mesh_stacks(vec![m1.clone(), m2.clone()]).await?; + + // Wait for magicsock to be told about peers from mesh_stacks. + println!("waiting for connection"); + let m1t = m1.clone(); + let m2t = m2.clone(); + time::timeout(Duration::from_secs(10), async move { + loop { + let ab = m1t.tracked_endpoints().await.contains(&m2t.public()); + let ba = m2t.tracked_endpoints().await.contains(&m1t.public()); + if ab && ba { + break; } - }) - .await - .context("failed to connect peers")?; + } + }) + .await + .context("failed to connect peers")?; - println!("closing endpoints"); - m1.endpoint.close(0u32.into(), b"done").await?; - m2.endpoint.close(0u32.into(), b"done").await?; + println!("closing endpoints"); + m1.endpoint.close(0u32.into(), b"done").await?; + m2.endpoint.close(0u32.into(), b"done").await?; - assert!(m1.endpoint.conn().inner.is_closed()); - assert!(m2.endpoint.conn().inner.is_closed()); + assert!(m1.endpoint.conn().inner.is_closed()); + assert!(m2.endpoint.conn().inner.is_closed()); - println!("cleaning up"); - cleanup().await; - cleanup_mesh(); - } - Ok(()) - }).await + println!("cleaning up"); + cleanup().await; + cleanup_mesh(); + } + Ok(()) } #[tokio::test] diff --git a/iroh-net/src/test_utils.rs b/iroh-net/src/test_utils.rs index be1759d1ef..0d288b2c9b 100644 --- a/iroh-net/src/test_utils.rs +++ b/iroh-net/src/test_utils.rs @@ -1,10 +1,7 @@ //! Internal utilities to support testing. -use std::future::Future; - use tokio::runtime::RuntimeFlavor; use tracing::level_filters::LevelFilter; -use tracing_futures::WithSubscriber; use tracing_subscriber::fmt::format::FmtSpan; use tracing_subscriber::layer::{Layer, SubscriberExt}; use tracing_subscriber::util::SubscriberInitExt; @@ -47,14 +44,14 @@ pub(crate) fn setup_logging() -> tracing::subscriber::DefaultGuard { testing_subscriber().set_default() } -/// Invoke the future with test logging configured. -/// -/// This can be used to execute any future which uses tracing for logging, it sets up the -/// logging as [`setup_logging`] does but in a way which will work for both single and -/// multi-threaded tokio runtimes. -pub(crate) async fn with_logging(f: F) -> F::Output { - f.with_subscriber(testing_subscriber()).await -} +// /// Invoke the future with test logging configured. +// /// +// /// This can be used to execute any future which uses tracing for logging, it sets up the +// /// logging as [`setup_logging`] does but in a way which will work for both single and +// /// multi-threaded tokio runtimes. +// pub(crate) async fn with_logging(f: F) -> F::Output { +// f.with_subscriber(testing_subscriber()).await +// } /// Returns the a [`tracing::Subscriber`] configured for our tests. /// From 54b01be7b0ffdb6fa031e6594f579b3e21072161 Mon Sep 17 00:00:00 2001 From: Floris Bruynooghe Date: Thu, 20 Jul 2023 18:37:37 +0200 Subject: [PATCH 3/3] don't lie --- iroh-net/src/test_utils.rs | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/iroh-net/src/test_utils.rs b/iroh-net/src/test_utils.rs index 0d288b2c9b..d15d94d381 100644 --- a/iroh-net/src/test_utils.rs +++ b/iroh-net/src/test_utils.rs @@ -33,10 +33,7 @@ pub(crate) fn setup_logging() -> tracing::subscriber::DefaultGuard { match handle.runtime_flavor() { RuntimeFlavor::CurrentThread => (), RuntimeFlavor::MultiThread => { - panic!( - "setup_logging() does not work in a multi-threaded tokio runtime, \ - use with_logging() instead" - ); + panic!("setup_logging() does not work in a multi-threaded tokio runtime"); } _ => panic!("unknown runtime flavour"), }