proc-macros: #[traced_test] macro

[yaahc]

Feature Request

It's common to want to use tracing in tests because who doesn't want to use tracing everywhere. Right now this adds an extra bit of boiler plate to every test. Also it's not widely known (I think?) that tests in the same file run in multiple threads of the same process, so the global subscriber is shared between all tests. This is probably fine but it would be better for tests to use scoped subscribers for each test.

Crates

tracing-proc-macros

Motivation

Discussion with lucio and eliza on gitter

Proposal

We should introduce a new macro that takes the place of the #[test] macro and will expand to a test macro and the body of the function inside of a default scoped logger. In the future we can look into ways to configure the implicitly setup logger if such needs arise.

[BlinkyStitt]

What is the boilerplate that is currently needed? I need some logs in one of my tests right now and I'm not sure how to set it up.

Also, will #[traced_test] work with other macros that also define tests? I'm currently using https://crates.io/crates/test-case for some of my tests, and I'm not sure how to move them to async.

[hawkw]

What is the boilerplate that is currently needed? I need some logs in one of my tests right now and I'm not sure how to set it up.

Essentially, you would want something like this:

#[test] 
fn my_test() {
    let _guard = tracing_subscriber::fmt() 
        // any additional configuration of the subscriber you might want here..
        .set_default();
}

If you have tests involving multiple threads, you would probably want to share the subscriber with all those threads and have them all call set_default, or you would want to use a global default subscriber that's shared across all tests.

If you use a global default subscriber for tests, you would probably want each test to have a span with the test's name, so you can see which test an individual log came from. Something like this:

#[test] 
fn my_test() {
    // ignore the result this returns; as it will fail if another test has already created
    // the global default subscriber
    let _ = tracing_subscriber::fmt() 
        // any additional configuration of the subscriber you might want here..
        .try_init();

     let span = tracing::info_span!("my_test");
     let _enter = span.enter();

     // ... the rest of your test here ...
}

Even if we're not setting a global subscriber, we might still find it valuable to generate a span for the test name so that it's displayed in the log output if multiple tests are running at once.

Also, will #[traced_test] work with other macros that also define tests? I'm currently using https://crates.io/crates/test-case for some of my tests, and I'm not sure how to move them to async.

This depends on how the proc-macro is implemented. I think it could definitely be written in a way that would remain compatible with other attribute macros that generate tests, though this might be ordering-dependent.

As a side note, you may want to look at the test-env-log crate by @d-e-s-o, which (despite the name) also supports tracing. It may already do everything you need!

[eHammarstrom]

I remember taking a stab at this issue when I was looking into Rust and proc macros a number of lifetimes ago. I'll leave it here for someone willing to pull it through :)

https://github.com/eHammarstrom/tracing/blob/master/tracing-proc-macros/src/lib.rs

[hawkw]

@eHammarstrom thanks, that's a neat prototype! I wonder if, rather than taking the type-name of a Subscriber implementation and assuming it has a new function, you could take an arbitrary expression instead. That way, it would still work with subscriber implementations whose new constructor takes arguments, subscribers with multiple constructors, and subscribers with builders or other interfaces for configuring them.

[dbrgn]

This would be great. Any ideas how #[traced_test] could coexist with #[tokio::test] though?

[nhynes]

This would be great. Any ideas how #[traced_test] could coexist with #[tokio::test] though?

You just dump the rest of the attrs out:

use quote::quote;

pub fn test_attr(input: syn::ItemFn) -> proc_macro2::TokenStream {
    let { attrs, vis, sig, block } = &input;
    let test_attr = sig.asyncness.as_ref()
        .map(|_| quote!(#[tokio::test]))
        .unwrap_or_else(|| quote!(#[test]);

    quote! {
        #test_attr
        #(#attrs)*
        #vis #sig {
            crate::init_tracing();
            #block
        }
    }
}

[dbrgn]

I just published the tracing-test crate. Maybe that resolves this issue for some of you?