subscriber: Use `DateTime` as format for `std::time::SystemTime` #807

Pothulapati · 2020-07-11T19:02:44Z

Motivation

Fixes #791

Solution

This PR copies DateTime type from https://github.com/danburkert/kudu-rs
and updates the default FormatTime impl for SystemTime when chrono is disabled to use
DateTime Formatting instead of Debug

After this, the following output is emitted instead of the one shown in the issue.

2020-07-11T16:49:15.155481Z  INFO example_no_crono: preparing to shave yaks number_of_yaks=3
2020-07-11T16:49:15.155523Z  INFO example_no_crono::yak_shave: shaving yaks
2020-07-11T16:49:15.155580Z DEBUG shave{yak=1}: example_no_crono::yak_shave: hello! I'm gonna shave a yak. excitement="yay!"
2020-07-11T16:49:15.155607Z DEBUG shave{yak=1}: example_no_crono::yak_shave: yak shaved successfully
2020-07-11T16:49:15.155665Z DEBUG example_no_crono::yak_shave: yak=1 shaved=true
2020-07-11T16:49:15.155691Z DEBUG example_no_crono::yak_shave: yaks_shaved=1
2020-07-11T16:49:15.155714Z DEBUG shave{yak=2}: example_no_crono::yak_shave: hello! I'm gonna shave a yak. excitement="yay!"
2020-07-11T16:49:15.155765Z DEBUG shave{yak=2}: example_no_crono::yak_shave: yak shaved successfully
2020-07-11T16:49:15.155788Z DEBUG example_no_crono::yak_shave: yak=2 shaved=true
2020-07-11T16:49:15.155799Z DEBUG example_no_crono::yak_shave: yaks_shaved=2
2020-07-11T16:49:15.155820Z DEBUG shave{yak=3}: example_no_crono::yak_shave: hello! I'm gonna shave a yak. excitement="yay!"
2020-07-11T16:49:15.155870Z  WARN shave{yak=3}: example_no_crono::yak_shave: could not locate yak!
2020-07-11T16:49:15.155909Z DEBUG example_no_crono::yak_shave: yak=3 shaved=false
2020-07-11T16:49:15.155921Z ERROR example_no_crono::yak_shave: failed to shave yak! yak=3 error=shaving yak failed!
2020-07-11T16:49:15.155932Z DEBUG example_no_crono::yak_shave: yaks_shaved=2
2020-07-11T16:49:15.155941Z  INFO example_no_crono: yak shaving completed. all_yaks_shaved=false

Signed-off-by: Tarun Pothulapati [email protected]

This PR copies DateTime type from https://github.com/danburkert/kudu-rs and updates the default FormatTime impl when chrono is disabled to use DateTime Formatting. Signed-off-by: Tarun Pothulapati <[email protected]>

Pothulapati · 2020-07-11T19:04:05Z

tracing-subscriber/src/fmt/time.rs

+/// [1] http://git.musl-libc.org/cgit/musl/tree/src/time/__secs_to_tm.c
+/// [2] https://c2rust.com/
+///
+/// This is directly copy-pasted from https://github.com/danburkert/kudu-rs/blob/c9660067e5f4c1a54143f169b5eeb49446f82e54/src/timestamp.rs#L5-L18


I directly copy pasted this code from along with tests, Is this the right way to give credits? or is there a better way?
@hawkw

This personally works for me, although I also think it'd be fair to just credit musl, since the code is really just a machine translation of __secs_to_tm with very light cleanup (essentially doing whatever clippy said).

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw · 2020-07-12T00:23:20Z

tracing-subscriber/src/fmt/time.rs

+    #[test]
+    fn test_datetime() {


It looks like this test is failing on Windows: https://github.com/tokio-rs/tracing/pull/807/checks?check_run_id=861424835#step:4:891

I tried testing on a windows machine, and found that it was these test cases that were causing to panic.
https://github.com/Pothulapati/tracing/blob/1c7c70b91ba7504aa486f69209d609544eb17a4e/tracing-subscriber/src/fmt/time.rs#L463 (and this is not the conversion logic to DateTime but it was in the case helper closure) as they were using i64::Max ori64::Min with UNIX_EPOCH + Duration::new(secs as u64, micros * 1_000) and impl Add<Duration> for SystemTime panics if the resulting point in time cannot be represented by the underlying data structure as per https://doc.rust-lang.org/std/time/struct.SystemTime.html#panics

It is mentioned in the doc that The size of a SystemTime struct may vary depending on the target operating system. and as per rust-lang/rust#44394 (comment), the range for windows is way less than that of UNIX. 🤔

Also, As the duration in the test case is pretty high i.e giving the time +292277026596-12-04T15:30:07.000000Z. Should it matter?

Thanks

Hmm. I think timestamps in the year 292277026596 are pretty unlikely to occur any time soon. However, there are situations where weird timestamps can occur other than actually being in that year --- the system clock might be misconfigured or something.

I think it would be better to handle this case a little more gracefully than wrapping. We could probably add a check before doing that add, and if it would wrap, we could just print "Invalid timestamp" or something, rather than panicking.

For the short term, I think it would be okay to disable the specific tests which use the really high year value on Windows. We can do that by adding a cfg attribute:

#[cfg(not(target_os = "windows"))] { case("+292277026596-12-04T15:30:07.000000Z", i64::MAX, 0); case("+292277026596-12-04T15:30:06.000000Z", i64::MAX - 1, 0); case("-292277022657-01-27T08:29:53.000000Z", i64::MIN + 1, 0); }

If we do that, it would be good to have a comment explaining why those tests are disabled on Windows.

Probably also worth ccing @danburkert — he might want to be aware that the upstream version of this test doesn't work with Windows timestamps, too. :)

This commit uses conditional compilation primitives to make high SystemTime tests be skipped on windows along with some explanations Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw

This looks great now that the tests that fail on Windows are skipped. I had some pretty minor suggestions, and then I think this will be good to merge.

hawkw · 2020-07-14T16:36:36Z

tracing-subscriber/src/fmt/time.rs

+///
+/// This is directly copy-pasted from https://github.com/danburkert/kudu-rs/blob/c9660067e5f4c1a54143f169b5eeb49446f82e54/src/timestamp.rs#L5-L18
+#[derive(Debug, Clone, Copy, PartialEq, Eq)]
+pub struct DateTime {


This isn't part of the public API --- it's only used internally by the SystemTime formatter. Therefore, it doesn't need to be pub:

Suggested change

pub struct DateTime {

struct DateTime {

hawkw · 2020-07-14T16:41:15Z

tracing-subscriber/src/fmt/time.rs

+        while i32::from(DAYS_IN_MONTH[months as usize]) <= remdays {
+            remdays -= i32::from(DAYS_IN_MONTH[months as usize]);
+            months += 1
+        }
+
+        if months >= 10 {
+            months -= 12;
+            years += 1;
+        }
+
+        DateTime {
+            year: years + 2000,
+            month: (months + 3) as u8,
+            day: (remdays + 1) as u8,
+            hour: (remsecs / 3600) as u8,
+            minute: (remsecs / 60 % 60) as u8,
+            second: (remsecs % 60) as u8,
+            nanos,
+        }
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use std::i32;
+    use std::time::{Duration, UNIX_EPOCH};
+
+    use super::*;
+
+    #[test]
+    fn test_datetime() {
+        let case = |expected: &str, secs: i64, micros: u32| {
+            let timestamp = if secs >= 0 {
+                UNIX_EPOCH + Duration::new(secs as u64, micros * 1_000)
+            } else {
+                (UNIX_EPOCH - Duration::new(!secs as u64 + 1, 0)) + Duration::new(0, micros * 1_000)
+            };
+            assert_eq!(
+                expected,
+                format!("{}", DateTime::from(timestamp)),
+                "secs: {}, micros: {}",
+                secs,
+                micros
+            )
+        };
+
+        // Mostly generated with:
+        //  - date -jur <secs> +"%Y-%m-%dT%H:%M:%S.000000Z"
+        //  - http://unixtimestamp.50x.eu/
+
+        case("1970-01-01T00:00:00.000000Z", 0, 0);
+
+        case("1970-01-01T00:00:00.000001Z", 0, 1);
+        case("1970-01-01T00:00:00.500000Z", 0, 500_000);
+        case("1970-01-01T00:00:01.000001Z", 1, 1);
+        case("1970-01-01T00:01:01.000001Z", 60 + 1, 1);
+        case("1970-01-01T01:01:01.000001Z", 60 * 60 + 60 + 1, 1);
+        case(
+            "1970-01-02T01:01:01.000001Z",
+            24 * 60 * 60 + 60 * 60 + 60 + 1,
+            1,
+        );
+
+        case("1969-12-31T23:59:59.000000Z", -1, 0);
+        case("1969-12-31T23:59:59.000001Z", -1, 1);
+        case("1969-12-31T23:59:59.500000Z", -1, 500_000);
+        case("1969-12-31T23:58:59.000001Z", -60 - 1, 1);
+        case("1969-12-31T22:58:59.000001Z", -60 * 60 - 60 - 1, 1);
+        case(
+            "1969-12-30T22:58:59.000001Z",
+            -24 * 60 * 60 - 60 * 60 - 60 - 1,
+            1,
+        );
+
+        case("2038-01-19T03:14:07.000000Z", i32::MAX as i64, 0);
+        case("2038-01-19T03:14:08.000000Z", i32::MAX as i64 + 1, 0);
+        case("1901-12-13T20:45:52.000000Z", i32::MIN as i64, 0);
+        case("1901-12-13T20:45:51.000000Z", i32::MIN as i64 - 1, 0);
+
+        // Skipping these tests on windows as std::time::SysteTime range is low
+        // on Windows compared with that of Unix which can cause the following
+        // high date value tests to panic
+        #[cfg(not(target_os = "windows"))]
+        {
+            case("+292277026596-12-04T15:30:07.000000Z", i64::MAX, 0);
+            case("+292277026596-12-04T15:30:06.000000Z", i64::MAX - 1, 0);
+            case("-292277022657-01-27T08:29:53.000000Z", i64::MIN + 1, 0);
+        }
+
+        case("1900-01-01T00:00:00.000000Z", -2208988800, 0);
+        case("1899-12-31T23:59:59.000000Z", -2208988801, 0);
+        case("0000-01-01T00:00:00.000000Z", -62167219200, 0);
+        case("-0001-12-31T23:59:59.000000Z", -62167219201, 0);
+
+        case("1234-05-06T07:08:09.000000Z", -23215049511, 0);
+        case("-1234-05-06T07:08:09.000000Z", -101097651111, 0);
+        case("2345-06-07T08:09:01.000000Z", 11847456541, 0);
+        case("-2345-06-07T08:09:01.000000Z", -136154620259, 0);
+    }
+}


All the DateTime code is only used for formatting SystemTimes when the chrono feature is not enabled. We might want to guard it with #[cfg(not(feature = "chrono"))] conditional compilation attribute, so that it's not compiled in when chrono is used instead.

We'd need to add that attribute to the DateTime struct, and to every impl block for DateTime (as well as the tests). The easiest way to do that is probably to stick the whole thing in a module and put the attribute on the whole module:

#[cfg(not(feature = "chrono"))] mod datetime { // ... code goes here ... }

If you like, you could also put that module in a separate file. Up to you.

This change creates datetime into a new mod, which is only included and used when crono is disabled. Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw · 2020-07-14T17:53:51Z

tracing-subscriber/src/fmt/mod.rs

+#[cfg(not(feature = "chrono"))]
+mod datetime;


nit/take it or leave it: since this is used only in the time module, it could probably be a submodule of time rather than of fmt. but, not a big deal.

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw

This looks great! Thank you!

@mockersf

Changed - **fmt**: When the `chrono` dependency is enabled, the `SystemTime` timestamp now emits human-readable timestamps rather than using `SystemTime`'s fmt::Debug`implementation (`chrono` is still required for customized timestamp formatting) (#807) - **ansi**: Updated `ansi_term` dependency to 0.12 (#816) Added - **json**: `with_span_list` method to configure the JSON formatter to include a list of all spans in the current trace in formatting events (similarly to the text formatter) (#741) - **json**: `with_current_span` method to configure the JSON formatter to include a field for the _current_ span (the leaf of the trace) in formatted events (#741) - **fmt**: `with_thread_names` and `with_thread_ids` methods to configure `fmt::Subscriber`s and `fmt::Layer`s to include the thread name and/or thread ID of the current thread when formatting events (#818) Thanks to new contributors @mockersf, @keetonian, and @Pothulapati for contributing to this release!

@mockersf

### Changed - **fmt**: When the `chrono` dependency is enabled, the `SystemTime` timestamp now emits human-readable timestamps rather than using `SystemTime`'s fmt::Debug`implementation (`chrono` is still required for customized timestamp formatting) (#807) - **ansi**: Updated `ansi_term` dependency to 0.12 (#816) ### Added - **json**: `with_span_list` method to configure the JSON formatter to include a list of all spans in the current trace in formatting events (similarly to the text formatter) (#741) - **json**: `with_current_span` method to configure the JSON formatter to include a field for the _current_ span (the leaf of the trace) in formatted events (#741) - **fmt**: `with_thread_names` and `with_thread_ids` methods to configure `fmt::Subscriber`s and `fmt::Layer`s to include the thread name and/or thread ID of the current thread when formatting events (#818) Thanks to new contributors @mockersf, @keetonian, and @Pothulapati for contributing to this release!

Use DateTime as format for std::time::SystemTime

f013b08

This PR copies DateTime type from https://github.com/danburkert/kudu-rs and updates the default FormatTime impl when chrono is disabled to use DateTime Formatting. Signed-off-by: Tarun Pothulapati <[email protected]>

Pothulapati requested review from hawkw and a team as code owners July 11, 2020 19:02

Pothulapati commented Jul 11, 2020

View reviewed changes

fmt fix

1c7c70b

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw reviewed Jul 12, 2020

View reviewed changes

make high SystemTime value tests platform specific

1dbdbd2

This commit uses conditional compilation primitives to make high SystemTime tests be skipped on windows along with some explanations Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw reviewed Jul 14, 2020

View reviewed changes

move datetime into a new module

93c1243

This change creates datetime into a new mod, which is only included and used when crono is disabled. Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw reviewed Jul 14, 2020

View reviewed changes

new time module directory and include DateTime into it

5c17dae

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw approved these changes Jul 14, 2020

View reviewed changes

hawkw merged commit 56b841d into tokio-rs:master Jul 14, 2020

Pothulapati deleted the time-default branch July 15, 2020 02:01

hawkw mentioned this pull request Jul 17, 2020

subscriber: prepare to release 0.2.8 #823

Merged

str4d mentioned this pull request Jul 23, 2020

tracing-subscriber: 0.2.8 requires MSRV 1.43.0 #840

Closed

jeromegn mentioned this pull request Sep 24, 2020

subscriber: format chrono timestamps the same way as non-chrono #982

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

subscriber: Use `DateTime` as format for `std::time::SystemTime` #807

subscriber: Use `DateTime` as format for `std::time::SystemTime` #807

Uh oh!

Pothulapati commented Jul 11, 2020 •

edited

Loading

Uh oh!

Pothulapati Jul 11, 2020

Uh oh!

danburkert Jul 11, 2020

Uh oh!

hawkw Jul 12, 2020

Uh oh!

Pothulapati Jul 12, 2020 •

edited

Loading

Uh oh!

hawkw Jul 13, 2020 •

edited

Loading

Uh oh!

hawkw Jul 13, 2020

Uh oh!

hawkw left a comment

Uh oh!

hawkw Jul 14, 2020

Uh oh!

hawkw Jul 14, 2020

Uh oh!

hawkw Jul 14, 2020

Uh oh!

hawkw left a comment

Uh oh!

Uh oh!

subscriber: Use DateTime as format for std::time::SystemTime #807

subscriber: Use DateTime as format for std::time::SystemTime #807

Uh oh!

Conversation

Pothulapati commented Jul 11, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Motivation

Solution

Uh oh!

Pothulapati Jul 11, 2020

Choose a reason for hiding this comment

Uh oh!

danburkert Jul 11, 2020

Choose a reason for hiding this comment

Uh oh!

hawkw Jul 12, 2020

Choose a reason for hiding this comment

Uh oh!

Pothulapati Jul 12, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hawkw Jul 13, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hawkw Jul 13, 2020

Choose a reason for hiding this comment

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

hawkw Jul 14, 2020

Choose a reason for hiding this comment

Uh oh!

hawkw Jul 14, 2020

Choose a reason for hiding this comment

Uh oh!

hawkw Jul 14, 2020

Choose a reason for hiding this comment

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

subscriber: Use `DateTime` as format for `std::time::SystemTime` #807

subscriber: Use `DateTime` as format for `std::time::SystemTime` #807

Pothulapati commented Jul 11, 2020 •

edited

Loading

Pothulapati Jul 12, 2020 •

edited

Loading

hawkw Jul 13, 2020 •

edited

Loading