subscriber: add OffsetTime workaround for local offset #1772

marienz · 2021-12-09T12:43:41Z

Motivation

Currently, the time crate refuses to determine the local timezone
offset on Unix unless the program is single-threaded or the
unsound_local_offset feature is enabled. Because LocalTime
determines the local timezone offset every time it formats a message,
and tracing is frequently used in multi-threaded programs, LocalTime
effectively requires unsound_local_offset. unsound_local_offset is
inconvenient to enable and potentially dangerous.

Solution

Add an OffsetTime formatter that formats time with a fixed offset,
passed in when it is initialized. Make it convenient to initialize this
with the local timezone offset.

The main advantage of this formatter over LocalTime is that if it is
initialized early, it will succeed without unsound_local_offset. An
additional advantage is that the program can handle errors determining
the local offset, because they now occur in the program's initialization
code rather than in tracing's formatting code.

This is not a drop-in replacement for LocalTime, because it behaves
differently if the program keeps running across a DST change.
LocalTime will pick up the new local offset, while OffsetTime will
continue to use the offset in effect when the program started.

Fixes #1771

Currently, the `time` crate refuses to determine the local timezone offset on Unix unless the program is single-threaded or the `unsound_local_offset` feature is enabled. Because `LocalTime` determines the local timezone offset every time it formats a message, and `tracing` is frequently used in multi-threaded programs, `LocalTime` effectively requires `unsound_local_offset`. `unsound_local_offset` is inconvenient to enable and potentially dangerous. Add an `OffsetTime` formatter that formats time with a fixed offset, passed in when it is initialized. Make it convenient to initialize this with the local timezone offset. The main advantage of this formatter over `LocalTime` is that if it is initialized early, it will succeed without `unsound_local_offset`. An additional advantage is that the program can handle errors determining the local offset, because they now occur in the program's initialization code rather than in tracing's formatting code. This is not a drop-in replacement for LocalTime, because it behaves differently if the program keeps running across a DST change. `LocalTime` will pick up the new local offset, while `OffsetTime` will continue to use the offset in effect when the program started.

marienz · 2021-12-09T12:46:08Z

tracing-subscriber/src/fmt/time/time_crate.rs

+impl<F> FormatTime for OffsetTime<F>
+where
+    F: time::formatting::Formattable,
+{
+    fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result {
+        let now = OffsetDateTime::now_utc().to_offset(self.offset);
+        format_datetime(now, w, &self.format)
+    }
+}


The actual formatting is not tested. My plan was to copy how LocalTime is tested, but I couldn't find its tests :) Happy to improve this if I missed something, or if you give me some pointers.

We don't really need tests for how the timestamp is actually formatted, because the way it's formatted is "however the time crate does it". :) Don't worry about adding tests for that.

hawkw

overall, this seems like a good approach to me. I had a few small comments mostly related to documentation.

hawkw · 2021-12-21T21:39:53Z

tracing-subscriber/src/fmt/time/time_crate.rs

+impl<F> FormatTime for OffsetTime<F>
+where
+    F: time::formatting::Formattable,
+{
+    fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result {
+        let now = OffsetDateTime::now_utc().to_offset(self.offset);
+        format_datetime(now, w, &self.format)
+    }
+}


We don't really need tests for how the timestamp is actually formatted, because the way it's formatted is "however the time crate does it". :) Don't worry about adding tests for that.

hawkw · 2021-12-21T21:40:25Z

tracing-subscriber/src/fmt/time/time_crate.rs

+    ///
+    /// Returns an error if the local time offset cannot be determined. This typically occurs in
+    /// multithreaded programs. To avoid this problem, initialize `OffsetTime` before forking
+    /// threads. When using Tokio, this means initializing `OffsetTime` before the Tokio runtime.


it might be worth adding an example showing initializing the formatter before starting a runtime? not a blocker though.

Done (I didn't realize I could use Tokio and write my own main in examples like these...).

I believe you can use Tokio because we have a dev dependency on tokio (it's used in a few other test).

Another approach I've used elsewhere in the documentation for tracing is to just do something like this:

//! # mod tokio { //! # fn spawn(_: impl Future<> {} //! # // fake versions of whatever other tokio APIs you need to show in the example... //! # } //! // the rest of the example...

hawkw · 2021-12-21T21:41:29Z

tracing-subscriber/src/fmt/time/time_crate.rs

+/// [formatter]: https://docs.rs/time/0.3/time/formatting/trait.Formattable.html
+/// [`time` crate]: https://docs.rs/time/0.3/time/
+#[derive(Clone, Debug)]
+#[cfg_attr(docsrs, doc(cfg(feature = "time")))]


this states that the type requires the time feature, but it looks like all the methods implemented for this type also require the local-time feature...should the type itself also require that feature flag?

OffsetTime::local_rfc_3339 requires local-time, but OffsetTime::init and OffsetTime::format_time (our impl FormatTime) do not. It should be possible (although admittedly unusual) to use OffsetTime with a non-local offset (not needing time's local-offset feature at all). And if our caller uses OffsetTime::init and calls current_local_offset themselves it seemed reasonable to have them enable the local-offset feature on the time crate themselves, rather than having them use our local-time feature just so we can turn on that time feature for them (we won't be doing anything with local time ourselves).

Please let me know if I'm overlooking something.

hawkw · 2021-12-23T21:07:48Z

ping @marienz, are you still planning on working on this? if not, i'm happy to apply the remaining suggestions so we can go ahead and get it merged!

marienz · 2021-12-26T10:30:07Z

Comments (hopefully) addressed, sorry for the delay.

hawkw · 2021-12-27T18:57:26Z

Looks like the CI failure was a spurious GitHub Actions issue, so I've restarted it.

hawkw

Okay, this looks good to me. Thanks again for the PR!

hawkw · 2021-12-27T18:59:40Z

tracing-subscriber/src/fmt/time/time_crate.rs

+    ///
+    /// Returns an error if the local time offset cannot be determined. This typically occurs in
+    /// multithreaded programs. To avoid this problem, initialize `OffsetTime` before forking
+    /// threads. When using Tokio, this means initializing `OffsetTime` before the Tokio runtime.


I believe you can use Tokio because we have a dev dependency on tokio (it's used in a few other test).

Another approach I've used elsewhere in the documentation for tracing is to just do something like this:

//! # mod tokio { //! # fn spawn(_: impl Future<> {} //! # // fake versions of whatever other tokio APIs you need to show in the example... //! # } //! // the rest of the example...

@marienz

# 0.3.5 (Dec 29, 2021) This release re-enables `RUST_LOG` filtering in `tracing_subscriber::fmt`'s default initialization methods, and adds an `OffsetLocalTime` formatter for using local timestamps with the `time` crate. ### Added - **fmt**: Added `OffsetLocalTime` formatter to `fmt::time` for formatting local timestamps with a fixed offset ([#1772]) ### Fixed - **fmt**: Added a `Targets` filter to `fmt::init()` and `fmt::try_init()` when the "env-filter" feature is disabled, so that `RUST_LOG` is still honored ([#1781]) Thanks to @marienz and @ishitatsuyuki for contributing to this release! [#1772]: #1772 [#1781]: #1781

@marienz

# 0.3.5 (Dec 29, 2021) This release re-enables `RUST_LOG` filtering in `tracing_subscriber::fmt`'s default initialization methods, and adds an `OffsetLocalTime` formatter for using local timestamps with the `time` crate. ### Added - **fmt**: Added `OffsetLocalTime` formatter to `fmt::time` for formatting local timestamps with a fixed offset ([#1772]) ### Fixed - **fmt**: Added a `Targets` filter to `fmt::init()` and `fmt::try_init()` when the "env-filter" feature is disabled, so that `RUST_LOG` is still honored ([#1781]) Thanks to @marienz and @ishitatsuyuki for contributing to this release! [#1772]: #1772 [#1781]: #1781

ghost · 2022-01-05T02:12:02Z

@marienz @hawkw

hi, thank you for this nice support, but i have a question.

I’m using tokio and setup the code by following your example, but the error came up. Any idea is appreciated.

thread 'main' panicked at 'could not get local time offset: IndeterminateOffset', crates/rest/src/main.rs:22:50
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[Finished running. Exit status: 101]

The code is like below. I surely initialize tracing offset before async fn.

// main.rs

use tracing_subscriber::fmt::time::OffsetTime;
use tracing_subscriber::EnvFilter;

fn main() {
    dotenv::dotenv().ok();
    let style = std::env::var("RUST_LOG_STYLE").unwrap_or_else(|_| "auto".into());
    let tracing_format = std::env::var("TRACING_FORMAT").unwrap_or_else(|_| "ansi".into());

    let builder = tracing_subscriber::fmt()
        .with_env_filter(EnvFilter::from_default_env())
        .with_timer(OffsetTime::local_rfc_3339().expect("could not get local time offset"))
        .with_ansi(style.to_lowercase() != "never");

    match tracing_format.as_str() {
        "json" => builder.json().init(),
        _ => builder.init(),
    };
    if let Err(e) = run() {
        tracing::error!("{:?}", e);
    };
}

#[tokio::main]
async fn run() -> hyper::Result<()> {
    //…
    tracing::debug!("listening");
    //…
}

Cargo tool is like this.

// Cargo.toml
tracing-subscriber = { version = "0.3.5", features = ["json", "env-filter", "local-time"] }

My environment is like this

### Version

│   │   │   └── tracing v0.1.29
│   │   │       ├── tracing-attributes v0.1.18 (proc-macro)
│   │   │       └── tracing-core v0.1.21
│   │   ├── tracing v0.1.29 (*)
├── tracing v0.1.29 (*)
├── tracing v0.1.29 (*)
│   │   └── tracing v0.1.29 (*)
│   │   └── tracing v0.1.29 (*)
├── tracing v0.1.29 (*)
├── tracing-subscriber v0.3.5
│   ├── tracing v0.1.29 (*)
│   ├── tracing-core v0.1.21 (*)
│   ├── tracing-log v0.1.2
│   │   └── tracing-core v0.1.21 (*)
│   └── tracing-serde v0.1.2
│       └── tracing-core v0.1.21 (*)

### Platform

Darwin C02FK4Y8MD6R 20.6.0 Darwin Kernel Version 20.6.0: Tue Oct 12 18:33:42 PDT 2021; root:xnu-7195.141.8~1/RELEASE_X86_64 x86_64

marienz · 2022-01-06T13:21:22Z

Unfortunately it looks like my example code will currently fail on MacOS (thanks for including the platform you're on!). For now, you'll need the special unsound_local_offset flags on that platform. The next release of the time crate looks like it will fix this.

Although the time crate says you can get IndeterminateOffset for any reason, there are currently really two reasons you may get it:

You've spawned threads before determining the local offset. I checked the dotenv crate and it doesn't look like it does that, and although it's possible you have code running before main I don't think that is likely.
The time crate is unable to determine if you've spawned threads. It looks like the currently released version of the time crate knows how to do this on Linux, and although their CHANGELOG only mentions "FreeBSD, OpenBSD, and NetBSD" as other supported platforms in the next release, they've actually migrated to a separate crate for thread count detection, and that crate supports MacOS.

So once those crates release (or if you depend on a new enough git snapshot...), I'd expect your code to work.

Until then, you might want to use OffsetTime instead of LocalTime anyway for (somewhat theoretical, to be honest) safety reasons. Using LocalTime with unsound_local_offset is unsafe if the process environment changes at runtime, while using OffsetTime with unsound_local_offset on MacOS is safe as long as you're not spawning threads early. The latter is easier to manually check for.

(If you have any further issues, it's probably easier to file an issue and CC me on it than to use this pull request.)

ghost · 2022-01-06T21:41:16Z

hi marienz, thank you for detail answer.

yeah time seems not to support it until v3.5, while master is already fixed but released code is like this, so...

https://github.com/time-rs/time/blob/6b8cdd3d9ec07c027e3aa6b9c8a69f4e6fd568dd/src/sys/local_offset_at/unix.rs#L111-L129

thank you very much again, I'll wait then!!!

ghost · 2022-01-21T04:32:07Z

0.3.6 time.rs is released a few hours ago, and now it's working. thank you very much

time-rs/time@3ff4543#diff-06572a96a58dc510037d5efa622f9bec8519bc1beab13c9f251e97e657a9d4edR27

## Motivation Currently, the `time` crate refuses to determine the local timezone offset on Unix unless the program is single-threaded or the `unsound_local_offset` feature is enabled. Because `LocalTime` determines the local timezone offset every time it formats a message, and `tracing` is frequently used in multi-threaded programs, `LocalTime` effectively requires `unsound_local_offset`. `unsound_local_offset` is inconvenient to enable and potentially dangerous. ## Solution Add an `OffsetTime` formatter that formats time with a fixed offset, passed in when it is initialized. Make it convenient to initialize this with the local timezone offset. The main advantage of this formatter over `LocalTime` is that if it is initialized early, it will succeed without `unsound_local_offset`. An additional advantage is that the program can handle errors determining the local offset, because they now occur in the program's initialization code rather than in tracing's formatting code. This is not a drop-in replacement for LocalTime, because it behaves differently if the program keeps running across a DST change. `LocalTime` will pick up the new local offset, while `OffsetTime` will continue to use the offset in effect when the program started. Fixes tokio-rs#1771

@marienz

# 0.3.5 (Dec 29, 2021) This release re-enables `RUST_LOG` filtering in `tracing_subscriber::fmt`'s default initialization methods, and adds an `OffsetLocalTime` formatter for using local timestamps with the `time` crate. ### Added - **fmt**: Added `OffsetLocalTime` formatter to `fmt::time` for formatting local timestamps with a fixed offset ([tokio-rs#1772]) ### Fixed - **fmt**: Added a `Targets` filter to `fmt::init()` and `fmt::try_init()` when the "env-filter" feature is disabled, so that `RUST_LOG` is still honored ([tokio-rs#1781]) Thanks to @marienz and @ishitatsuyuki for contributing to this release! [tokio-rs#1772]: tokio-rs#1772 [tokio-rs#1781]: tokio-rs#1781

marienz requested review from a team and hawkw as code owners December 9, 2021 12:43

marienz commented Dec 9, 2021

View reviewed changes

Merge branch 'v0.1.x' into tracing-subscriber-offset

036d2b5

hawkw reviewed Dec 21, 2021

View reviewed changes

Add an example using OffsetTime with Tokio

543db37

Merge branch 'v0.1.x' into tracing-subscriber-offset

d7c9dc1

hawkw approved these changes Dec 27, 2021

View reviewed changes

hawkw merged commit f8be43b into tokio-rs:v0.1.x Dec 28, 2021

hawkw mentioned this pull request Dec 28, 2021

can't compile tracing-subscriber with --cfg unsound_local_offset in macos because time still doesn't release patch #1805

Closed

hawkw mentioned this pull request Dec 30, 2021

subscriber: prepare to release 0.3.5 #1810

Merged

marienz deleted the tracing-subscriber-offset branch December 30, 2021 12:34

davidbarsky mentioned this pull request Sep 26, 2023

chore: backport roughly a year's worth of changes #2728

Merged

subscriber: add OffsetTime workaround for local offset #1772

subscriber: add OffsetTime workaround for local offset #1772

Uh oh!

Conversation

marienz commented Dec 9, 2021

Motivation

Solution

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hawkw commented Dec 23, 2021

Uh oh!

marienz commented Dec 26, 2021

Uh oh!

hawkw commented Dec 27, 2021

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ghost commented Jan 5, 2022

Uh oh!

marienz commented Jan 6, 2022

Uh oh!

ghost commented Jan 6, 2022

Uh oh!

ghost commented Jan 21, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants