Logging improvements

[nazar-pc]

This PR is an improved version of paritytech/substrate#14760

Here I changed default timestamp format in logging to include timezone offset (as requested by @koute) and added CLI option to print timestamps in UTC using the same format as the default in tracing-subscriber.

Before:

2023-09-12 02:57:03 Substrate Node    

After:

2023-09-12 02:57:03+01:00 Substrate Node    

UTC:

2023-09-12T01:57:03.061965Z Substrate Node    

I also did benchmarks and found that these changes introduce ~10% performance hit for local time, while UTC performance is about the same as local time was before these changes.

Before:

fast_local_time         time:   [18.366 ns 18.392 ns 18.421 ns]
chrono_local            time:   [320.59 ns 320.83 ns 321.07 ns]

After:

fast_local_time/local   time:   [19.919 ns 19.927 ns 19.937 ns]
fast_local_time/utc     time:   [18.582 ns 18.590 ns 18.599 ns]

There are also some changes to colors:

• Support for NO_COLOR, though better approach might be to remove --disable-log-color altogether and use supports-color that automatically takes this environment variable into account (see fmt subscriber should honor NO_COLOR by default tokio-rs/tracing#2388 and Uses ANSI escape codes in dumb terminal in Sublime Text tokio-rs/tracing#2214).
• On Windows colors are disabled by default because otherwise they make logs hard to read since PowerShell doesn't handle escape characters teh way *nix shells do

I recommend reviewing individual commits rather than final diff for convenience.

[nazar-pc]

Any feedback here? I hope this isn't controversial.

[koute]

Hm, I'd probably prefer to have this take a parameter, e.g. --timestamp-format=$format where $format can be local (default) or iso8601 (since what you've done is not just to force UTC timestamps - you've changed the format of the timestamp to be like iso8601). It's also more forward compatible if we'd want to add other formats, or make the timestamp format fully configurable with an strftime-like string.

[nazar-pc]

I like that, but ISO 8601 is not just UTC, so I it seems like there should still be a distinction between UTC and non-UTC in logs if you really want to have local time there (I suspect that is current expectation from Substrate users that would be undesirable to change).

[koute]

Well then, it could be iso8601-utc I guess?

[nazar-pc]

Hm, I read about ISO 8601, what a mess... There are so many way to compose valid ISO 8601 date and time that it is hardly helpful to name an option like that. Technically both local and UTC time in PR description are valid RFC 3339 formats, so the only difference between them is local vs UTC time and T vs between date and time (both valid).

What about something like this?:

• --timestamp-format=default
• --timestamp-format=tracing-subscriber

default is the current default of Substrate, tracing-subscriber is format used in that crate. Standard doesn't say anything about number of digits for fractional seconds, so both 3 and 6 is valid according to RFC 3339.

Here is helpful visualization: https://ijmacd.github.io/rfc3339-iso8601/

[koute]

Can you rewrite this so that:

1. There are two timestamp caches, one for local time and another for UTC. (This will make CachedTimestamp::last_utc unnecessary.)
2. The body of this function would essentially be something like this:

// Outside:
fn format_time_local(...) { ... }
fn format_time_utc(...) { ... }
// ...
// Inside::
let unix_time = ...;
if self.utc {
    format_time_utc(...)
} else {
    format_time_local(...)
}

This way there will only be a single toplevel if self.utc check.

[koute]

6 digits for the fractional part seems somewhat excessive; why not use 3 like in the non-UTC case?

The logger's asynchronous anyway so this much precision is practically useless. It'll just take extra space in the logs for no real benefit.

[nazar-pc]

The reason is to make it identical to what tracing-subscriber does by default. We use Substrate as a library in a bigger application, so having various logging formats interleaved is awkward and undesirable.

[koute]

Okay, that's reasonable if that's the tracing-subscriber default.

[koute]

In theory the current timezone can change, so this should not assume that the timezone stays constant.

This is only done once per second, so its fine to do this unconditionally.

[koute]

The with_fractional should not be silently ignored when using UTC timestamps.

Either we make it obey with_fractional, or the timestamp format should be an enum (so then in the UTC case there just wouldn't be with_fractional)

[nazar-pc]

@koute I'd really like to find the design which works for everyone and upstream it. Do you have any fresh thoughts on how to approach this?

[nazar-pc]

Closing as I no longer have interest in driving this forward, our chain is switching away from Substrate's runner and as such we can use normal tracing-subscriber directly without fighting Substrate's logging system.