Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(tests): Improve test_utils to warn about mutli-runtime tests #1280

Merged
merged 6 commits into from
Jul 21, 2023
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 0 additions & 1 deletion iroh-net/src/magicsock.rs
Original file line number Diff line number Diff line change
Expand Up @@ -3086,7 +3086,6 @@ 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()?,
};
Expand Down
64 changes: 62 additions & 2 deletions iroh-net/src/test_utils.rs
Original file line number Diff line number Diff line change
@@ -1,38 +1,98 @@
//! Internal utilities to support testing.

use tokio::runtime::RuntimeFlavor;
use tracing::level_filters::LevelFilter;
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"
flub marked this conversation as resolved.
Show resolved Hide resolved
);
}
_ => 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: Future>(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)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

what does this do?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It also shows a log line when a span is closed. I find this really nice as you very clearly see things finish.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Every thing that makes spans more readable is welcome. By the way - is there a way to use RUST_LOG to get rid of the span info in each log line? I find it a bit overwhelming sometimes...

2023-07-19T12:47:00.734742Z DEBUG conn{name=magic-78c000c451139ad8}:derp.actor:recv_detail:client-connect{key=PublicKey(78c000c451139ad8a8a77e9b5fe752b18320a9c551c0959ee71a85f24c82de15)}: rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

By the way - is there a way to use RUST_LOG to get rid of the span info in each log line? I find it a bit overwhelming sometimes...

2023-07-19T12:47:00.734742Z DEBUG conn{name=magic-78c000c451139ad8}:derp.actor:recv_detail:client-connect{key=PublicKey(78c000c451139ad8a8a77e9b5fe752b18320a9c551c0959ee71a85f24c82de15)}: rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    

Yeah, it is a lot of stuff. Though I find it very useful information. I sometimes wonder about making some kind of interactive tui to explore tracing output more interactively... but someone else will have to write it probably.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

though often you only have to go scan all the way to the right for the few things you care about. that's a little mitigating i guess.

.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.
Expand Down