Crash in tests upon upgrade from v1.15.0 to v1.15.1

[rye]

The following (MWE) test has regressed to an unexpected failure upon upgrade from v1.15.0 to v1.15.1.

#[test]
fn foo() {
    simple_logger::SimpleLogger::new().init().unwrap();

    log::error!("asdf");
}

The new error upon upgrade is:

---- foo stdout ----
thread 'foo' panicked at 'Could not determine the UTC offset on this system. Possible causes are that the time crate does not implement "local_offset_at" on your system, or that you are running in a multi-threaded environment and the time crate is returning "None" from "local_offset_at" to avoid unsafe behaviour. See the time crate's documentation for more information. (https://time-rs.github.io/internal-api/time/index.html#feature-flags): IndeterminateOffset', /home/kristofer/.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/simple_logger-1.15.1/src/lib.rs:360:64
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

This does not happen when the same code is put into src/main.rs and run via cargo run. It seems to just be when running in a test suite. (I discovered this in one of my tests/*.rs files on a recent CI run.)

I am running Linux 5.15.4-arch1-1, cargo and rustc 1.57.0 (latest). The same crash also happens in an ubuntu-20.04 GitHub Actions environment.

📝 A successful test on log = 0.4.14 and simple_logger = 1.15.0:

~/crash > cat Cargo.toml
[package]
name = "crash"
version = "0.1.0"
edition = "2021"

[dependencies]
log = "=0.4.14"
simple_logger = "=1.15.0"
 ~/crash > cargo clean; cargo +stable test
   Compiling libc v0.2.111
   Compiling log v0.4.14
   Compiling cfg-if v1.0.0
   Compiling itoa v0.4.8
   Compiling time-macros v0.2.3
   Compiling lazy_static v1.4.0
   Compiling atty v0.2.14
   Compiling colored v1.9.3
   Compiling time v0.3.5
   Compiling simple_logger v1.15.0
   Compiling crash v0.1.0 (~/crash)
    Finished test [unoptimized + debuginfo] target(s) in 1.92s
     Running unittests (target/debug/deps/crash-1fa0a31e9a43fbdf)

running 1 test
test foo ... ok

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

     Running unittests (target/debug/deps/crash-44d68fedfb08f7e9)

running 0 tests

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

   Doc-tests crash

running 0 tests

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

📝 The exact same test, but replacing =1.15.0 with =1.15.1 in Cargo.toml:

 ~/crash > cat Cargo.toml
[package]
name = "crash"
version = "0.1.0"
edition = "2021"

[dependencies]
log = "=0.4.14"
simple_logger = "=1.15.1"
 ~/crash > cargo clean; cargo +stable test
   Compiling libc v0.2.111
   Compiling log v0.4.14
   Compiling time-macros v0.2.3
   Compiling itoa v0.4.8
   Compiling cfg-if v1.0.0
   Compiling lazy_static v1.4.0
   Compiling atty v0.2.14
   Compiling colored v1.9.3
   Compiling time v0.3.5
   Compiling simple_logger v1.15.1
   Compiling crash v0.1.0 (~/crash)
    Finished test [unoptimized + debuginfo] target(s) in 1.98s
     Running unittests (target/debug/deps/crash-c4caeb7678a19db2)

running 1 test
test foo ... FAILED

failures:

---- foo stdout ----
thread 'foo' panicked at 'Could not determine the UTC offset on this system. Possible causes are that the time crate does not implement "local_offset_at" on your system, or that you are running in a multi-threaded environment and the time crate is returning "None" from "local_offset_at" to avoid unsafe behaviour. See the time crate's documentation for more information. (https://time-rs.github.io/internal-api/time/index.html#feature-flags): IndeterminateOffset', ~/.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/simple_logger-1.15.1/src/lib.rs:360:64
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    foo

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

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

[borntyping]

This is an expected failure: there was a bug in 1.15.0 that meant features that should have been enabled by default disabled (#35, 4dda64b, 156e7d6).

The raised error is likely correct in this situation - by default, cargo test runs with multiple thread and so the time crate refuses to get the local time offset (time crate feature flags, time-rs/time#293). This obviously isn't ideal but avoids a potential segfault. Some options for working around this are running cargo without threads (cargo test -- --test-threads=1) or configuring the time crate to risk a segfault and access the timezone offset anyway (RUSTFLAGS="--cfg unsound_local_offset"). A option I'd like to add if this issue is around for a while is to support using UTC time instead and avoiding this code path entirely.

[borntyping]

Or the obvious alternative - which I didn't think of in the above comment - is to simply disable the timestamps feature which would give you exactly the same behaviour as 1.15.0. This wouldn't behave like <1.15.0 as timestamps would not be displayed in the logs.

[rye]

Thanks for your quick and thorough response! I figured it was more of a failure because of an upstream behavior (in the time crate) but wanted to document that upgrading broke my build (esp. in case anyone else runs into this). I did confirm that I'm getting an IndeterminateOffset result from the underlying method in another test, so this does make sense. Feel free to close this issue since it sounds like this is expected.

As far as fixes go, I'll probably opt-in to the unsafe behavior or disable the timestamps feature when testing, since I have lots of tests to run. (Consider this a vote in favor of making local offsets opt-in, too — my servers all use UTC timestamps, actually. I might try my hand at adding that if that'd be a useful feature!)

[borntyping]

I'd be more than happy to see a contribution adding that feature! It should be a little easier to add than some previous similar features as it can use the existing timestamps feature flag.

[borntyping]

Released v1.16.0 with options to use UTC timestamps. Thanks!

[borntyping]

UTC timestamps are now the default in simple_logger 2.0.0.