Adjust time resolution to microseconds

[jmhbnz]

Historic capnslog timestamps are in microsecond resolution. We need to match that when we migrate to the zap logger.

The standard zap time encoder options are listed here: https://github.com/uber-go/zap/blob/077b03eb1c5f4ed0703209766e4c897bb88ae6fb/zapcore/encoder.go#L171

Unfortunately none of these completely matched both the precision and format of the historic capnslog format so I've added a custom encoder function that matches exactly.

Here is a comparison:

Format	Example
Old capnslog	2023-02-02 13:50:27.813478
Zap RFC3339NanoTimeEncoder	2023-02-03T20:08:58.299954658+13:00
Zap RFC3339TimeEncoder	2023-02-03T20:09:52+13:00
Zap EpochMillisTimeEncoder	1675408253432.4639
Zap EpochNanosTimeEncoder	1675408290557930192
Zap custom function	2023-02-03 20:12:20.789477

Fixes #15236.

Edit: Here is a sample of the new log output:

 ➜ ./bin/etcd --logger=zap
{"level":"warn","ts":"2023-02-03 20:42:37.898898","caller":"embed/config.go:790","msg":"it isn't recommended to use default name, please set a value for --name. Note that etcd might run into 
issue when multiple members have the same default name","name":"default"}
{"level":"info","ts":"2023-02-03 20:42:37.898953","caller":"etcdmain/etcd.go:64","msg":"Running: ","args":["./bin/etcd","--logger=zap"]}
{"level":"warn","ts":"2023-02-03 20:42:37.898969","caller":"etcdmain/etcd.go:96","msg":"'data-dir' was empty; using default","data-dir":"default.etcd"}
{"level":"info","ts":"2023-02-03 20:42:37.898997","caller":"etcdmain/etcd.go:107","msg":"server has already been initialized","data-dir":"default.etcd","dir-type":"member"}
{"level":"warn","ts":"2023-02-03 20:42:37.899006","caller":"embed/config.go:790","msg":"it isn't recommended to use default name, please set a value for --name. Note that etcd might run into 
issue when multiple members have the same default name","name":"default"}

[ahrtr]

Please squash the commits, and could you build & run etcd and paste a couple of the log message?

[ahrtr]

LGTM

Thanks @jmhbnz

Could you backport this PR to release-3.5 and release-3.4?

[jmhbnz]

Thanks @ahrtr - Just want to double check the full e2e suite passes in case there are any tests that also need fixing etc.

Happy to help with backporting, what process does the etcd project follow to do that, are we just cherry picking a commit back to a release branch or something similar? Thanks 🙏🏻

Edit: Looks like one test needed to be updated to reflect the format correction, have fixed that.

[ahrtr]

release-3.5 and 3.4 have very big different code structure, you'd better to backport the change manually.

[jmhbnz]

release-3.5 and 3.4 have very big different code structure, you'd better to backport the change manually.

3.5 Backport raised #15240

It looks like 3.4 didn't have any of the zap logger content, only 3.5 did so I'm not sure we need to take it back that far?

[ahrtr]

3.4:

etcd/pkg/logutil/zap.go

Line 46 in b4e3ed7

EncodeTime: zapcore.ISO8601TimeEncoder,

[serathius]

Please don't make a breaking change

[ptabor]

I would vote for RFC3339NanoTimeEncoder as the default for v3.6. It's 3 digits too long IMHO, but better than use standard than something custom just to have usec instead of nanos.

For v3.4 & v3.5 we should have this flag driven to avoid a breaking change. So most likely flag in v3.6 as well
(just we a different default).

[serathius]

I would vote for RFC3339NanoTimeEncoder as the default for v3.6. It's 3 digits too long IMHO, but better than use standard than something custom just to have usec instead of nanos.

@ptabor Don't disagree, but we can make it a feature request handled in separate issue/PR?

[ptabor]

I would vote for RFC3339NanoTimeEncoder as the default for v3.6. It's 3 digits too long IMHO, but better than use standard than something custom just to have usec instead of nanos.

@ptabor Don't disagree, but we can make it a feature request handled in separate issue/PR?

I'm lost. Why would we go over 2 changes of the same exact logic instead of deciding what's the expected end state ?

[ptabor]

2006-01-02T15:04:05.999999999Z07:00.
To double check:

@serathius Are you saying change:

2006-01-02T15:04:05.000Z0700  ->   2006-01-02T15:04:05.999999Z0700

is backward compatible and can be backported - as it stays within ISO 8601 standard:

YYYY-MM-DDThh:mm:ssTZD (eg 1997-07-16T19:20:30+01:00)
   Complete date plus hours, minutes, seconds and a decimal fraction of a
second

s    = one or more digits representing a decimal fraction of a second

After checking RFC3339 seems more restricted subset of ISO8601
(https://stackoverflow.com/questions/522251/whats-the-difference-between-iso-8601-and-rfc-3339-date-formats)

---

If so - seems acceptable. For v3.4 sounds a little brave.

[ptabor]

It's interesting that the old code using ISO8601TimeEncoder was writing:
2006-01-02T15:04:05.999999Z0700
While according to ISO8601 (https://en.wikipedia.org/wiki/ISO_8601#Time_offsets_from_UTC) it should be:
2006-01-02T15:04:05.999999Z+07:00

that's I assume the biggest risk to backward compatibility

[ahrtr]

It's interesting that the old code using ISO8601TimeEncoder was writing: 2006-01-02T15:04:05.999999Z0700 While according to ISO8601 (https://en.wikipedia.org/wiki/ISO_8601#Time_offsets_from_UTC) it should be: 2006-01-02T15:04:05.999999Z+07:00

that's I assume the biggest risk to backward compatibility

Does it mean that ISO8601TimeEncoder isn't compliant with standard? Probably we should raise an issue to zap?

[ahrtr]

Based on https://en.wikipedia.org/wiki/UTC_offset, all the following formats are valid,

 ±[hh]:[mm], ±[hh][mm], or ±[hh]

So RFC3339NanoTimeEncoder should be OK.

[ahrtr]

@jmhbnz Please move forward per the discussion above.

• Use RFC3339NanoTimeEncoder for main branch;

[serathius]

So RFC3339NanoTimeEncoder should be OK.
@jmhbnz Please move forward per the discussion above.

Let's wait until there is a clear agreement on the topic.

Can we first summarize, what are the options, what issues we see in zap that should be reported and what is the preferred solution so everyone can agree on?

@serathius Are you saying change:

 2006-01-02T15:04:05.000Z0700  ->   2006-01-02T15:04:05.999999Z0700

is backward compatible and can be backported - as it stays within ISO 8601 standard:

Yes, as 4.2.2.4 section of ISO 8601 standard states about decimal fraction:

The interchange parties, dependent upon the application, shall agree the number of digits in the decimal
fraction. The format shall be [hhmmss,ss], [hhmm,mm] or[hh,hh] as appropriate (hour minute second, 
hour minute,  and  hour, respectively),  with as many digits as necessary following the decimal sign. A
decimal fraction shall have at least one digit. 

[ptabor]

For me the concern is the colon in timezone.

For 3.4, 3.5 we should be using 2006-01-02T15:04:05.999999Z0700 (it's no colons in timezone)

For 3.6 I don't have strong opinion, but leaning towards the more standard (RFC3339NanoTimeEncoder):
2006-01-02T15:04:05.999999999Z07:00

[serathius]

ok, makes sense. Let's report lack of colon to zap people and see what they have to say about this.

[serathius]

Reading through https://www.loc.gov/standards/datetime/iso-tc154-wg5_n0038_iso_wd_8601-1_2016-02-16.pdf looks like zap made a strange choice to combine extended format (includes semicolon) and basic format (minimal representation without separators).

2.3.3
basic format
format of a date and time representation or date and time format representation comprising the	
minimum number of time elements necessary for the accuracy required
Note to entry: The basic format should be avoided in plain text.
2.3.4
extended format
extension of the basic format that includes additional separators

[serathius]

Let's merge it for clear backport. @jmhbnz please send a separate PR that will change format for v3.6 to RFC3339NanoTimeEncoder.