Logging from tests appears not to work as described in the docs

[wykurz]

Calling the init() defined as:

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

in my tests appears not to produce any log output:

RUST_LOG=debug cargo test
    Finished test [unoptimized + debuginfo] target(s) in 0.02s
     Running target/debug/deps/log_fail-ea6852f038016c7e

running 1 test
test tests::test1 ... ok

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

However running env_logger::init() does seem to work:

#[cfg(test)]
mod tests {
    #[test]
    fn test1() {
    env_logger::init();
        debug!("hello!");
    info!("hello!");
    error!("hello!");
    assert!(true);
    }
}

RUST_LOG=debug cargo test Finished test [unoptimized + debuginfo] target(s) in 0.01s Running target/debug/deps/log_fail-ea6852f038016c7e

running 1 test [2020-11-23T05:39:32Z DEBUG log_fail::tests] hello! [2020-11-23T05:39:32Z INFO log_fail::tests] hello! [2020-11-23T05:39:32Z ERROR log_fail::tests] hello! test tests::test1 ... ok

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

This is with env_logger 0.8.2 and log 0.4.11.

[KodrAus]

Thanks for the report! It's possible something changed about the way the test framework captures output so I'll take a look. If we don't need is_test anymore that would be great.

[detly]

I just hit a similar problem that seems like it's related. If not, I'll open a separate issue.

Cargo.toml:

[package]
name = "logtest"
version = "0.1.0"
edition = "2018"

[dependencies]
log = "0.4"
env_logger = "0.8"

tests/test1.rs:

use env_logger;

#[test]
fn one() {
    env_logger::builder()
        .is_test(true)
        .format_timestamp(None)
        .try_init()
        .expect("Could not initialise test logging");
}

#[test]
fn two() {
    env_logger::builder()
        .is_test(true)
        .format_timestamp(None)
        .try_init()
        .expect("Could not initialise test logging");
}

Running cargo test gives:

running 2 tests
test two ... ok
test one ... FAILED

failures:

---- one stdout ----
thread 'one' panicked at 'Could not initialise test logging: SetLoggerError(())', tests/test1.rs:9:10
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

failures:
    one

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

error: test failed, to rerun pass '--test test1'

[ditsing]

Running cargo test gives:

running 2 tests
test two ... ok
test one ... FAILED

failures:

---- one stdout ----
thread 'one' panicked at 'Could not initialise test logging: SetLoggerError(())', tests/test1.rs:9:10
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

failures:
    one

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

error: test failed, to rerun pass '--test test1'

Logger can only be setup once per process. The two tests share the same process so you cannot set up logger in both. You can either make sure try_init() is only called once (e.g. by using std::sync::Once), or wait for subprocess testing.

[mpizenberg]

I also thought that logging from tests did not work, but in my case, it was actually that I did not set the level filter correctly. Now all is working as it should when initializing with:

fn init_log() {
    let _ = env_logger::builder()
        .filter_level(LevelFilter::Trace)
        .is_test(true)
        .try_init();
}

And as expected from the doc, if I do not set is_test(true), the logs go to stderr and are mixed with the output from cargo test instead of being captured and output for the failing tests. So for me, all is working well.

@wykurz could this be that you just need to add filter_level to your env logger builder?

By the way, it is normal that your logs do not appear when the test is passing. is_test(true) is meant so that test logs are captured for each test and only reported for failing tests, colocated with the test output.

[wykurz]

This is still not working for me. Here's full example:

#[macro_use]
extern crate log;

#[cfg(test)]
mod tests {
    fn init() {
        let _ = env_logger::builder()
            .filter_level(log::LevelFilter::Trace)
            .is_test(true)
            .try_init();
    }

    #[test]
    fn test_foo() {
        init();
        info!("foo");
    }
}

fn main() {
    env_logger::init();
    info!("bar");
}

When I run the binary all looks fine:

RUST_LOG=info cargo run
   Compiling logtest v0.1.0 (/home/mateusz/projects/logtest)
    Finished dev [unoptimized + debuginfo] target(s) in 0.49s
     Running `target/debug/logtest`
[2021-08-15T02:11:14Z INFO  logtest] bar

However running the test, I still see no log output:

RUST_LOG=info cargo test
   Compiling logtest v0.1.0 (/home/mateusz/projects/logtest)
    Finished test [unoptimized + debuginfo] target(s) in 0.61s
     Running unittests (target/debug/deps/logtest-627269ea88a03c02)

running 1 test
test tests::test_foo ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out;
finished in 0.00s

Am I doing something wrong here?

On Fri, Aug 6, 2021 at 5:53 AM Matthieu Pizenberg @.***> wrote:

I also thought that logging from tests did not work, but in my case, it was actually that I did not set the level filter correctly. Now all is working as it should when initializing with:

fn initlog() { let = env_logger::builder() .filter_level(LevelFilter::Trace) .is_test(true) .try_init(); }

And as expected from the doc, if I do not set is_test(true), the logs go to stderr and are mixed with the output from cargo test instead of being captured and output for the failing tests. So for me, all is working well.

@wykurz https://github.com/wykurz could this be that you just need to add filter_level to your env logger builder?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/env-logger-rs/env_logger/issues/186#issuecomment-894145978, or unsubscribe https://github.com/notifications/unsubscribe-auth/AADWBCMHAOX76GSCN5SOR6TT3OWIXANCNFSM4T7AXQCA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email .

[ditsing]

@wykurz Have you tried cargo test -- --nocapture? Test outputs are captured by default. They will be silently swallowed if the test succeeds.

[wykurz]

Ah, that helps! Indeed, I now see the log output (FYI also w/o filter_level Matthieu). Thanks Jing!

BTW I was looking for an option like this earlier but running:

cargo test --help

did not show it. Only after running this I see --nocapture:

cargo test -- --help

Very confusing! Although off topic for this thread.

Thanks again!

On Sat, Aug 14, 2021 at 11:42 PM Jing Yang @.***> wrote:

@wykurz https://github.com/wykurz Have you tried cargo test -- --nocapture? Test outputs are captured by default. They will be silently swallowed if the test succeeds.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/env-logger-rs/env_logger/issues/186#issuecomment-898990718, or unsubscribe https://github.com/notifications/unsubscribe-auth/AADWBCO7SPEEZM7D2SQAPDLT44ZT7ANCNFSM4T7AXQCA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email .