cargo test not capturing log outputs

[Kleptine]

I can't seem to get cargo test to properly capture either STDOUT or STDERR when logging with env_logger. My understanding is that cargo should capture both when tests pass and only show the results when tests fail.

Instead, all logs from env_logger/log macros are interleaved as the tests are running, and none are displayed in the "--- test_name stdout ----" section.

Here's the code I'm using:

extern crate env_logger;

#[test]
fn test_name() -> Result<(), Box<Error>> {
    env_logger::init();

    println!("PRINTLN"); // gets captured properly

    // none of these are captured
    error!("error"); 
    info!("info");
    trace!("trace");
    Err(Box::from("test"))
}

I don't have the same issue using another crate such as simple_logger:

#[test]
fn test_name() -> Result<(), Box<Error>> {
    simple_logger::init().unwrap();

    println!("PRINTLN");
    error!("error");
    info!("info");
    trace!("trace");
    Err(Box::from("test"))
}

[KodrAus]

Thanks for the report @Kleptine!

It looks like the problem here is that libtest uses a hidden, unstable mechanism for capturing the streams that's used internally by the println! and eprintln! macros, but not when using the stdout or stderr functions directly. It's a bit of a shame, but will need some thought to work around, since termcolor needs the stdout and stderr handles for writing.

[Kleptine]

Ooh, yikes. That's a bit of a pain. Seems like something that should be fixed on the Rust-side long term, though. It keeps you from having any kind of reasonable logging practices in your tests. :(

I suppose termcolor could be modified to output through println! as a workaround, or perhaps you could somehow pass termcolor a file handle that ended up redirecting back through println!? It'd be pretty messy. Are you aware of any bugs against rust for this behavior?

[KodrAus]

Yeh, I agree the behaviour is pretty surprising here.

I think we could forward termcolors printing logic through a writer given by the println macro, with the cost of Rust's format machinery around it.

I'll spend some time spiking that out, and raise an issue on rust-lang/rust to see whether it's come up before.

[Kleptine]

Appreciate it -- thanks! I'm fine with using simple_logger for the time being, at least in tests, so no rush.

[KodrAus]

It's not a perfect solution, but on the master branch you can work around this by compiling env_logger without default features:

[dev-dependencies]
env_logger = { version = "*", default-features = false, git = "https://github.com/sebasmagri/env_logger.git" }

That removes the termcolor dependency and uses print! and eprint! as fallbacks. Those are properly captured by cargo test.

Until the libtest machinery changes I think this is about as good as we can do here.

[Kleptine]

Thanks -- that sounds like a plan. No terminal colors is :( but better than having to swap logging libraries.

Let me know if there's anything I can do to support the necessary libtest changes.

[KodrAus]

I'm not too sure what shape the libtest capturing infrastructure will eventually end up with, and it doesn't seem to be moving in any particular direction right now.

This is 'fixed' in env_logger 0.6 by disabling default features:

[dev-dependencies]
env_logger = { version = "~0.6", default-features = false }

I'll go ahead and close this one now that we've got a published workaround, but we can revisit this sometime in the future if the situation changes! Thanks @Kleptine

[Kleptine]

Circling back on this real quick. I just upgraded over to 0.6 with default-features=false. I'm still not getting test captures for error!, where println! works fine. I'm on Rust 1.31.0 Windows MSVC.

Is this still working on your end?

[KodrAus]

Oh that's interesting... Do you have env_logger as a regular dependency in your library too? For example, this won't capture properly in tests:

[dependencies.env_logger]
version = "0.6"

[dev-dependencies.env_logger]
default-features = false

To make it more robust we should probably add a test feature to env_logger that you can enable to ensure capturing works:

[dependencies.env_logger]
version = "0.6"

[dev-dependencies.env_logger]
features = ["test"]

[KodrAus]

Alternatively, we could add a env_logger::test_init function that uses println! as the format, and never panics if initialized multiple times?

[Kleptine]

Ah, yes, I'm definitely using it as a regular dependency. I'm assuming that's overriding the flags in my test crate?

The second option of just having a test_init with println!, might honestly be the cleanest way to go. I'm fine wrapping it in a std::Once, so either way on that is fine.

[vincentdephily]

The test_init() helper sounds like a nice to have, as it gets rid of the double-init gotcha. Feels a bit out of scope though ?

Another API we could potentially use is a Target::Unittest value. It's fairly discoverable, serves as a reminder to remain compatible with libtest (currently at the cost of losing colors), and allows limiting the potential overhead to test code. It's still a bit awkward, but I want different log level defaults for my tests, so I have a test-specific init anyway.

[KodrAus]

@vincentdephily That's an interesting idea, I think it's reasonable to expect callers to want to be able to choose where their captured logs end up though, but something like that where we track whether the caller has asked for a test output behind the scenes could be a way to go and shouldn't be intrusive to the rest of the API.

[KodrAus]

Alrighty, I've opened #127 to fix this up, which lets us do something like:

#[macro_use]
extern crate log;

fn add_one(num: i32) -> i32 {
    info!("add_one called with {}", num);
    num + 1
}

#[cfg(test)]
mod tests {
    use super::*;
    extern crate env_logger;

    fn init() {
        let _ = env_logger::builder().is_test(true).try_init();
    }

    #[test]
    fn it_adds_one() {
        init();

        info!("can log from the test too");
        assert_eq!(3, add_one(2));
    }

    #[test]
    fn it_handles_negative_numbers() {
        init();

        info!("logging from another test");
        assert_eq!(-7, add_one(-8));
    }
}

So that cargo test can capture log records. It's not perfect, but isn't too intrusive (it affects the termcolor implementation a little bit), and if it was possible to detect that you were running in libtest from the environment then we could try do this by default.

[jcaesar]

If you're wondering why this doesn't work for you, you might be running into rust-lang/rust#42474 - println is not properly captured in threads.

[Edit:] This is fixed with current (1.49) cargo/rustc/…