Per-test file logging

[torsteingrindvik]

Hi, thanks for the great lib.

I have 100+ tests, and I would like to set up a log file for each of them.
Currently I initialize tracing via static TRACING: Once = Once::new(); using std::sync::Once, so whichever test runs first initializes tracing globally.

However I want to have each test write to a separate file.

Is it possible to:

1. Make the global subscriber output to a different file based on metadata
2. Add new sinks to the global tracing instance at runtime
3. Something else?

Any tips appreciated!

[hawkw]

I can think of a couple approaches that might be useful:

Using the thread-local scoped dispatcher

One option, potentially the easiest, would just be to use the thread-local scoped trace dispatcher for each test, rather than initializing a global subscriber. You could write code like this:

use std::{fs::File, error::Error};
use tracing::dispatch::DefaultGuard;

fn init_tracing(test_name: &str) -> Result<DefaultGuard, Box<dyn Error>> {
    let file = File::create(format!("{}.log", test_name))?; // or however you want to name the log file

    let subscriber = tracing_subscriber::fmt()
        // ... however you would configure the subscriber goes here ...
        .with_writer(Arc::new(file));

    // Set the default subscriber for the _current thread_, returning a guard that unsets 
    // the default subscriber when it is dropped.
    Ok(tracing::subscriber::set_default(subscriber))
}

#[test]
fn my_great_test() {
    // the defautl subscriber will write to `my_great_test.log` for the duration of this test
    let _guard = init_tracing("my_great_test").unwrap();

    // ... the actual test ...
}

#[test]
fn my_other_cool_test() {
    // the defautl subscriber will write to `my_other_cool_test.log` for the duration of this test
    let _guard = init_tracing("my_other_cool_test").unwrap();

    // ... the actual test ...
}

// ... and so on ...

If this approach works for you, it might be the easiest way to get logs directed to a separate file for each test. You could also use std::thread::current().name() to determine the name of the test automatically; by default, Rust will run each test in a thread whose name is the test's own name.

With that said, there are some cases where this approach may not work and you will have to use the global default dispatcher. If your tests spawn their own threads, the default dispatcher context will not be propagated to the spawned threads unless you do so manually. For example, you will have to write:

#[test]
fn my_test_that_spawns_threads() {
    let _guard = init_tracing("my_test_that_spawns_threads").unwrap();

    // ... test code ...

    // spawn a new thread, propagating the dispatcher context
    let dispatch = tracing::dispatcher::Dispatch::default();
    std::thread::spawn(move || {
         let _guard = tracing::dispatcher::set_default(dispatch);
         // now the spawned thread is inside the same dispatcher context as 
         // the main test thread

         // ... more code ...
    });
}

However, if threads are spawned in the code under test, or in external libraries, this approach may not work as well. If you're using #[tokio::test], this should work by default, because the default test runtime is single-threaded; but if you're overriding the default runtime like #[tokio::test(flavor = "multi_thread")], this won't work, because the runtime's worker threads will be outside the dispatcher context.

Implementing MakeWriter

If using per-thread scoped dispatchers won't work for you and you need to use the global default dispatcher, you can use the MakeWriter trait from tracing-subscriber to configure where output is written to. The MakeWriter::make_writer_for method is called by the fmt subscriber to produce a writer for each event, with the event's metadata. You could implement MakeWriter by having this method return a writer that writes to a different file based on the event's metadata. This will require more effort than using the per-thread scoped dispatcher, but it would allow you to write events to different files based on their metadata, while continuing to use the global default dispatcher.

[hawkw]

As a side note, I also thought it might be helpful to point out that your current approach for initializing the global default subscriber using a std::sync::Once is not actually necessary. The set_global_default method will already only allow the global default dispatcher to be set a single time; it returns an error if the global default subscriber has already been set.

If you have a bunch of tests that all try to set the global default dispatcher, you can simply ignore the error that's returned if the global default was already set. This will get you exactly the same behavior as using std::sync::Once, but requiring less boilerplate code on your part. :)

You could simply write:

fn init_tracing() {
    let subscriber = /* ... however you configure your subscriber ... */;
    // If this is the first time this function is called, it will set the global 
    // default subscriber and return `Ok(())`, otherwise, it will do nothing
    // and return an error. Since we are calling it in every test, we can
    // simply ignore the error; all it means is that another test has already
    // set the global default. 
    let _ = tracing::subscriber::set_global_default(subscriber);
}

#[test]
fn my_test_1() {
    init_tracing():

    // ... actual test ...
}

#[test]
fn my_test_2() {
    init_tracing():

    // ... actual test ...
}

// ... and so on ...

Essentially, you can think of tracing::subscriber::set_global_default/tracing::dispatcher::set_global_default as having their own, internal std::sync::Once that is used to ensure the global default is not set twice.

Hope that's helpful! :)

[torsteingrindvik]

Thank you for the very thorough replies, I appreciate this a lot!

And surprising that you mention #[tokio::test(flavor = "multi_thread")] as my testing is async based and I have tried both the default and this flavor.

The insights about spawning threads etc. I think will be useful then.

But as a side note I was surprised when my tests ran in a virtual machine with only two allocated vCPUs, and they seemed to make progress only two at a time instead of 100+ at a time.

I assumed tokio test would do Amazing Async Global Threadpool Stuff™ and tests sitting on an .await point would allow other tests to progress, but it seems they are decoupled.
So I might have to move away from basing my testing around #[test]/[tokio::test].

But your tips will likely help me either way so thanks again.

(EDIT: oh and yes I will remove the use of std::sync::Once that was a nice bonus)

[hawkw]

I assumed tokio test would do Amazing Async Global Threadpool Stuff™ and tests sitting on an .await point would allow other tests to progress, but it seems they are decoupled.

#[tokio::test] will create a separate Tokio runtime for each test. I believe this is intended to ensure that every test is completely isolated and they cannot interfere with each other. If that's not what you want, and you want to optimize for running tests as quickly as possible on a small number of cores, I imagine you could write your own code for creating a single tokio runtime (e.g. using std::sync::Once) and having each test spawn tasks on that runtime and wait for them to complete. But, that seems somewhat out of scope for tracing --- might be a good question to ask on the tokio repo's discussions, instead! :)

[torsteingrindvik]

you could write your own code for creating a single tokio runtime (e.g. using std::sync::Once) and having each test spawn tasks on that runtime and wait for them to complete

Interesting thought, I will consider this.
And ask them over there if I need help around that.

Thanks again:)

[cjwcommuny]

If using per-thread scoped dispatchers won't work for you and you need to use the global default dispatcher, you can use the MakeWriter trait from tracing-subscriber to configure where output is written to. The MakeWriter::make_writer_for method is called by the fmt subscriber to produce a writer for each event, with the event's metadata. You could implement MakeWriter by having this method return a writer that writes to a different file based on the event's metadata.

I came across the same problem, but still found this solution is not applicable. I would like to set up a log file for each of the test function.

To implement MakeWriter, I attempted to use a Mutex<HashMap<String, Mutex<File>>>, but I encountered two obstacles:

1. There is no way to close the corresponding file when a test function is finished, leading to potential resource leaks.
2. This implementation leads to the error "returns a value referencing data owned by the current function".