borntyping / rust-simple_logger

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

Panic using local timestamps #84

Open allenap opened 8 months ago

allenap commented 8 months ago

simple_logger v4.2.0

Using:

    simple_logger::SimpleLogger::new()
        .with_level(log::LevelFilter::Warn)
        .with_local_timestamps()
        .with_colors(stdout().is_terminal())
        .env()
        .init()?;

I get:

The application panicked (crashed).
Message:  Could not determine the UTC offset on this system. Consider displaying UTC time instead. 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
Location: /Users/gavin/.cargo/registry/src/index.crates.io-6f17d22bba15001f/simple_logger-4.2.0/src/lib.rs:447

This is inside a Tokio block:

    let rt = tokio::runtime::Runtime::new()?;
    rt.block_on(async {
      log::info!("... something ...");
    })

so the error message makes sense – but perhaps a logging library shouldn't panic in this kind of situation.

What would work well for my scenario (i.e. it may not be useful for others):

Or:

borntyping commented 8 months ago

Hi! :wave:

  • The UTC offset is captured at initialisation time and used as a fallback.
  • If there's no offset at initialisation time, emit a single warning. Log messages should then be emitted in UTC.
  • When the fallback value is used, emit a warning to say that the offset may be inaccurate.

You shouldn't do this — offsets can change while a program is running, usually for summer time transitions. It might be nice if we could check if we can get the offset during initialisation, but I'm not sure that would cover your case as the initialisation is likely happening before the threaded code starts.

When the offset cannot be determined, logs are emitted in UTC.

A timestamps option to use UTC or local time might be a nice feature—I don't work on this library much but am usually happy to accept pull requests that keep within the library's simple spirit! However I'm not sure it's particularly ideal to have logs that might change format over time or in different parts of the program. In your example the threaded code would output UTC timestamps, but any log statements executed during the applications setup would use local timestamps.

You can find a bit more about the history of this issue on https://github.com/borntyping/rust-simple_logger/issues/52 and the issues linked to it. I'd recommend switching to UTC timestamps in any case where this complexity becomes relevant.

Since I last wrote about this issue time also added an API for changing it's soundness, which will enable getting a UTC offset in threaded code as long as you are absolutely confident the environment will not be mutated at the same time as UTC offsets are obtained. https://time-rs.github.io/internal-api/time/util/local_offset/fn.set_soundness.html