Log capturing in unit tests

[dbrgn]

When writing unit tests, cargo captures output to stdout by default.

#[test]
fn print() {
    println!("Logging with println!");
}

This will not print the text to the terminal, unless cargo test is started with the -- --nocapture argument.

However, with slog this does not seem to work:

// main.rs

fn main() {
    println!("Hello, world!");
}

#[cfg(test)]
mod tests {
    use slog::{Drain, o, info};

    #[test]
    fn print() {
        println!("Logging with println!");
    }

    #[test]
    fn log_to_stdout() {
        let decorator = slog_term::TermDecorator::new().stdout().build();
        let drain = slog_term::CompactFormat::new(decorator).build();
        let log = slog::Logger::root(std::sync::Mutex::new(drain).fuse(), o!());
        info!(log, "Logging to stdout");
    }

    #[test]
    fn log_to_stderr() {
        let decorator = slog_term::TermDecorator::new().stderr().build();
        let drain = slog_term::CompactFormat::new(decorator).build();
        let log = slog::Logger::root(std::sync::Mutex::new(drain).fuse(), o!());
        info!(log, "Logging to stderr");
    }
}

Running this with cargo test will print:

$ cargo test -- --test-threads=1
    Finished test [unoptimized + debuginfo] target(s) in 0.02s
     Running target/debug/deps/asdf-5593e16ab0d57485

running 3 tests
test tests::log_to_stderr ... Feb 17 17:33:41.976 INFO Logging to stderr
ok
test tests::log_to_stdout ... Feb 17 17:33:41.977 INFO Logging to stdout
ok
test tests::print ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

Neither stdout nor stderr logs are captured.

I realize that this is probably due to some pecularity in how cargo handles capturing, but is there some kind of drain that logs in a cargo log capturing compatible way (possibly using println) that can be used in tests?

[Flakebi]

You need to use let decorator = slog_term::PlainDecorator::new(std::io::stdout());. The TermDecorator will print directly to the terminal if possible.

[dpc]

I might be wrong, but I think tests in Rust are not intercepting stdio, but only calls to println and alikes. I think someone had a slog Drain/serializer that is using println instead of writing to stdio directly to help with slog logging in tests.

[dpc]

Ha. It's in slog-term directly. https://github.com/slog-rs/term/blob/1f749568fe03f73be0142f2fdf9ac80ee961efc6/src/lib.rs#L1392

[dpc]

What's the point of writing all this documentation when no one reads it. :D https://docs.rs/slog-term/2.5.0/slog_term/struct.TestStdoutWriter.html

[Flakebi]

Right, I thought I got it working but I failed to run the test… Thanks!

[Flakebi]

Also, for future reference because I just fixed this, I needed to use Mutex instead of Async in #[tokio::test]:

let logger = {
	let decorator = slog_term::PlainDecorator::new(slog_term::TestStdoutWriter);
	let drain = Mutex::new(slog_term::FullFormat::new(decorator).build()).fuse();

	slog::Logger::root(drain, o!())
};

[dpc]

Async should work too, no? Particularly in async code I would recommend async drain, because you want to minimize the executor thread being stuck on io. Locking a mutex over a drain is OK in a slow synchronous code, but in async, I doubt it will be good enough.

[Flakebi]

It works, yes, but I get all the console output that I don’t want for succeeding unit tests. With the Mutex I only get the output when a test fails :)

[dpc]

Really? Why? Are you using both slog_term::TestStdoutWriter + Async?

[Flakebi]

Yes, the variant that works good for me is this:

#[tokio::test]
async fn test_things() -> Result<()> {
	let logger = {
		let decorator = slog_term::PlainDecorator::new(slog_term::TestStdoutWriter);
		let drain = Mutex::new(slog_term::FullFormat::new(decorator).build()).fuse();

		slog::Logger::root(drain, o!())
	};
	info!(logger, "Hi from async test");
	Ok(())
}

[Bathtor]

I know this has been closed for a while, but I'd like to save other people some headache and time, trying to figure out why this doesn't work with Async (in fact it doesn't work with Mutex either, if you are actually logging something from another thread):

rust-lang/rust#42474

TL;DR: Rust's testing framework uses thread locals to mark that output should be captured, so creating any threads in a test case and passing a logger (or just even calling just println!) there is not going to work.

Perhaps this could be mentioned in the docs at some point?

[dpc]

Please fill a PR!

[Bathtor]

Please fill a PR!

There you go: slog-rs/term#32

[dpc]

Thanks!

[purew]

I'm using the following for unittests in slog 2.7.0, but I really miss the nice colored output I get elsewhere

let decorator = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter);
let drain = std::sync::Mutex::new(slog_term::FullFormat::new(decorator).build()).fuse();
let logger = Logger::root(drain, slog::o!());

I can't find a way to get the colors back. Does anyone have any ideas?

[dpc]

@purew https://docs.rs/slog-term/2.8.0/slog_term/struct.TermDecoratorBuilder.html#method.force_color to make it not detect that it's not printing to stdout (as test suite is capturing the output, so it's not going direcly to TTY)

[purew]

@purew https://docs.rs/slog-term/2.8.0/slog_term/struct.TermDecoratorBuilder.html#method.force_color to make it not detect that it's not printing to stdout (as test suite is capturing the output, so it's not going direcly to TTY)

Hmm, how would I combine this with the code I pasted above? PlainSyncDecorator does not have force_color and TermDecoratorBuilder does not seem to take TestStdoutWriter as input?

[dpc]

Use TermDecorator instead of PlainSyncDecorator (still with TestStdoutWriter). Use e.g. for refere.ce https://docs.rs/slog-term/2.8.0/slog_term/index.html#synchronization-via-mutex