Format and print time at which event has occurred

[TmLev]

As discussed in #49, new FormatTime trait is introduced and implemented for a few basic scenarios:

• () – do-nothing time formatter.
• Uptime – almost a copy-pasta from tracing_subscriber. Changed nanos to micros.
• LocalDateTime – current wall-clock time in the current timezone.
• UtcDateTime – current wall-clock time in the UTC timezone.

Here's an example of how it looks with UtcDateTime:

Logs from `examples/basic.rs`

1:main┐basic::hierarchical-example version=0.1
1:main├┐basic::hierarchical-example version=0.1
1:main│└┐basic::server host="localhost", port=8080
1:main│ ├─2023-03-31 10:27:25.122113 0ms  INFO basic starting
1:main│ ├─2023-03-31 10:27:25.427151 305ms  INFO basic listening
1:main│ ├┐basic::server host="localhost", port=8080
1:main│ │└┐basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │ ├─2023-03-31 10:27:25.427267 0ms DEBUG basic connected
1:main│ │ ├─2023-03-31 10:27:25.728098 300ms DEBUG basic message received, length=2
1:main│ │┌┘basic::conn peer_addr="82.9.9.9", port=42381
1:main│ ├┘basic::server host="localhost", port=8080
1:main│ ├┐basic::server host="localhost", port=8080
1:main│ │└┐basic::conn peer_addr="8.8.8.8", port=18230
1:main│ │ ├─2023-03-31 10:27:26.0303 302ms DEBUG basic connected
1:main│ │┌┘basic::conn peer_addr="8.8.8.8", port=18230
1:main│ ├┘basic::server host="localhost", port=8080
1:main│ ├┐basic::server host="localhost", port=8080
1:main│ │└┐basic::foomp 42 <- format string, normal_var=43
1:main│ │ ├─2023-03-31 10:27:26.030431 0ms ERROR basic hello
1:main│ │┌┘basic::foomp 42 <- format string, normal_var=43
1:main│ ├┘basic::server host="localhost", port=8080
1:main│ ├┐basic::server host="localhost", port=8080
1:main│ │└┐basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │ ├─2023-03-31 10:27:26.030491 0ms  WARN basic weak encryption requested, algo="xor"
1:main│ │ ├─2023-03-31 10:27:26.331355 300ms DEBUG basic response sent, length=8
1:main│ │ ├─2023-03-31 10:27:26.331516 301ms DEBUG basic disconnected
1:main│ │┌┘basic::conn peer_addr="82.9.9.9", port=42381
1:main│ ├┘basic::server host="localhost", port=8080
1:main│ ├┐basic::server host="localhost", port=8080
1:main│ │└┐basic::conn peer_addr="8.8.8.8", port=18230
1:main│ │ ├─2023-03-31 10:27:26.331738 0ms DEBUG basic message received, length=5
1:main│ │ ├─2023-03-31 10:27:26.633213 301ms DEBUG basic response sent, length=8
1:main│ │ ├─2023-03-31 10:27:26.633372 301ms DEBUG basic disconnected
1:main│ │┌┘basic::conn peer_addr="8.8.8.8", port=18230
1:main│ ├┘basic::server host="localhost", port=8080
1:main│ ├─2023-03-31 10:27:26.633815 1511ms  WARN basic internal error
1:main│ ├─2023-03-31 10:27:26.633901 1511ms ERROR basic this is a log message
1:main│ ├─2023-03-31 10:27:26.633946 1511ms  INFO basic exit
1:main│┌┘basic::server host="localhost", port=8080
1:main├┘basic::hierarchical-example version=0.1
1:main┘basic::hierarchical-example version=0.1

Closes #48. Supersedes #49.

[TmLev]

@davidbarsky ready for your review.

[TmLev]

@ten3roberts can you try this PR out and share your feedback?

[ten3roberts]

Looks nice and works on my end.

Would it be possible to add the UtcTime struct (maybe feature gate it) which allows a bit shorted and succint timestamps compared to the OffsetDateTime in addition for wasm32 support.

Perhaps the Uptime is a bit too precise

Uptime

OffsetDateTime

Perhaps some padding between the timestamp and span duration, as they are now back to back.

Thanks for your work

[TmLev]

• Uptime now shows up to microseconds (instead of nanoseconds).

  Example output

  

• Added padding after timestamp.
  Not sure whether timestamp should be dimmed (dark grey color like elapsed time has).

  Example output

  

• Renamed OffsetDateTime to LocalDateTime.

• Added UtcDateTime.
  Same as LocalDateTime, but omits offset since it is always zero.

  Example output

  

[TmLev]

@ten3roberts can you please tell me more about wasm32 support? Which part of this PR prevents wasm32 from being supported?

[ten3roberts]

Wow, looks much better

On wasm32-unknown-unknown Instant::now is not available and panics.

The time and chrono crates Utc and datetime can bind to js and the js Date api.

tracing-web mentions this in their readme

https://github.com/WorldSEnder/tracing-web#overview

[TmLev]

So what would you like me to do? Make a feature flag in tracing_tree for enabling time's wasm-bindgen feature?

[ten3roberts]

No, simply depending on time is enough, as the feature resolver will unify the wasm-bindgen feature which you add in the user crate

[TmLev]

Okay, got you.

@davidbarsky do you have time to review this PR?

[davidbarsky]

Sorry for the delay in looking at this: I haven't been able to review it depth because my employer is doing layoffs this week and I wanted to get some of the things I was working on done and released.

I'll give this a proper review in an hour.

[oli-obk]

I've been thinking about how to test this. A test could use a dummy FormatTime impl that uses interior mutability to increment the time by a fixed amount every time format_time is called. Please add a test like this so we have some minimal regression testing for this scheme.

[TmLev]

Made a test with an atomic counter which gets incremented each time its FormatTime implementation is supposed to be called. Is that what you had in mind?

P.S. GitHub is lagging hard right now, for some reason it doesn't show the latest commit.
P.S.S. Everything works now.

[oli-obk]

Is that what you had in mind?

No, but your test is better than the one I had in mind 😆

gonna let CI run its course and then merge it

[TmLev]

Looks like CI is done?..

[TmLev]

Can I ask you to publish a new release with this PR?

[oli-obk]

We're figuring out permissions and stuff. May take a bit with back and forth across a large timezone gap.

[oli-obk]

A new version with this change has been published