search

borntyping / rust-simple_logger

A rust logger that prints all messages with a readable output format.
https://crates.io/crates/simple_logger
MIT License
220 stars 48 forks source link

simple logger panics in async/multi-threaded environment possibly due to "local_offset_at" in `time-rs` dependency #48

Closed cromulentbanana closed 2 years ago

cromulentbanana commented 2 years ago

First, thanks for your contribution to rust logging!

As of version 1.16, I've oserved that simple logger will panic when executed in the tokio async runtime with the following output:

thread 'main' 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', /var/home/dlevin/.cargo/registry/src/github.com-1ecc6299db9ec823/simple_logger-1.16.0/src/lib.rs:409:85
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Panic in Arbiter thread.

I've provided an example repo that you can clone, in which this bug is triggered:

(analytics) ❯❯ git clone git@github.com:cryptobanana/simpleloggerpanic.git
Cloning into 'simpleloggerpanic'...
remote: Enumerating objects: 15, done.
remote: Counting objects: 100% (15/15), done.
remote: Compressing objects: 100% (12/12), done.
remote: Total 15 (delta 0), reused 15 (delta 0), pack-reused 0
Receiving objects: 100% (15/15), 15.29 KiB | 5.10 MiB/s, done.
(analytics) ❯❯ cd simpleloggerpanic
(analytics) ❯❯ cargo run
   Compiling simpleloggerpanic v0.1.0 (/tmp/simpleloggerpanic)
    Finished dev [unoptimized + debuginfo] target(s) in 5.88s
     Running `/home/dlevin/nobackup/cargo/debug/simpleloggerpanic`
2022-01-09 12:23:04,327 INFO [simpleloggerpanic] Logging with level INFO
2022-01-09 12:23:04,327 INFO [actix_server::builder] Starting 8 workers
thread 'main' 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', /var/home/dlevin/.cargo/registry/src/github.com-1ecc6299db9ec823/simple_logger-1.16.0/src/lib.rs:409:85
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Panic in Arbiter thread.

I realize this panic is probably not due directly to the simple logger codebase itself, but perhaps if the problem indeed lies in time-rs, then the dependency time-rs can be updated... or something.

Currently simple_logger v1.15 is not affected by this problem.

Many thanks in advance!

borntyping commented 2 years ago

This is a known issue (https://github.com/borntyping/rust-simple_logger/issues/43, https://github.com/borntyping/rust-simple_logger/issues/44, https://github.com/borntyping/rust-simple_logger/issues/47).

The time crate's documentation provides more information about this issue: https://time-rs.github.io/internal-api/time/index.html#feature-flags, as does this issue: https://github.com/time-rs/time/issues/293.

There's a list of workarounds for simple_logger, depending on how you'd prefer to deal with the issue (mostly taken from https://github.com/borntyping/rust-simple_logger/issues/43).

  1. Use UTC time: SimpleLogger::new().with_utc_timestamps().init().unwrap();
  2. Disable timestamps: SimpleLogger::new().without_timestamps().init().unwrap();
  3. Use the time crate's unsafe features: RUSTFLAGS="--cfg unsound_local_offset" (docs)

Older versions of simple_logger use a different dependency (chrono) which is vulnerable to the same problem the time crate is trying to avoid. The unsound_local_offset flag from the time crate makes it work the same way as the chrono crate. This problem still affects the latest version of the time crate.

borntyping commented 2 years ago

UTC timestamps are now the default in simple_logger 2.0.0.