Timestamp in inconsistent format (all seconds) in ETCD(v 3.5) logs for fileutil/fileutil.go

[ankitg-03]

What happened?

Hi,
We encountered an issue with the "timestamps" while printing the pod logs (ETCD version : 3.5)
We are unexpectedly getting the timestamp in seconds in log lines for fileutil/fileutil.go, whereas rest are in the format yyyy-MM-ddTHH:mm:ss.SSSZ

We would like to ask for more knowledge about the same to achieve the following format(yyyy-MM-ddTHH:mm:ss.SSSZ) ?

Note: The above issue is not seen in ETCD version 3.4

What did you expect to happen?

We expected timestamp format for logs to be the following yyyy-MM-ddTHH:mm:ss.SSSZ, same as all other logs.

How can we reproduce it (as minimally and precisely as possible)?

If folder permission is not 700 then we would get the message. In our case folder permission is 750 or 770, so we are getting the warn message with inconsistent timestamp format.

Anything else we need to know?

No response

Etcd version (please run commands below)

$ etcd --version
# paste output here
etcd Version: 3.5.3
Git SHA: 0452feec7
Go Version: go1.16.15
Go OS/Arch: linux/amd64

$ etcdctl version
# paste output here
etcdctl version: 3.5.3
API version: 3.5

Etcd configuration (command line flags or environment variables)

paste your configuration here

Etcd debug information (please run commands blow, feel free to obfuscate the IP address or FQDN in the output)

$ etcdctl member list -w table
# paste output here

$ etcdctl --endpoints=<member list> endpoint status -w table
# paste output here

Relevant log output

{"level":"warn","ts":1668163025.3963275,"caller":"fileutil/fileutil.go:57","msg":"check file permission","error":"directory \"/data\" exist, but the permission is \"dgrwxrwxr-x\". The recommended permission is \"-rwx------\" to prevent possible unprivileged access to the data"}
{"level":"warn","ts":1668163025.39648,"caller":"fileutil/fileutil.go:57","msg":"check file permission","error":"directory \"/data/member/snap\" exist, but the permission is \"dgrwxrwx---\". The recommended permission is \"-rwx------\" to prevent possible unprivileged access to the data"}
{"level":"info","ts":"2022-11-11T10:37:05.399Z","caller":"etcdserver/backend.go:81","msg":"opened backend db","path":"/data/member/snap/db","took":"2.867032ms"}
{"level":"info","ts":"2022-11-11T10:37:05.421Z","caller":"etcdserver/server.go:529","msg":"No snapshot found. Recovering WAL from scratch!"}
{"level":"info","ts":"2022-11-11T10:37:05.426Z","caller":"etcdserver/raft.go:483","msg":"restarting local member","cluster-id":"a3b1444a2a7a13d3","local-member-id":"5e87fd08fc96d0cd","commit-index":683}
{"level":"info","ts":"2022-11-11T10:37:05.426Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"5e87fd08fc96d0cd switched to configuration voters=()"}
{"level":"info","ts":"2022-11-11T10:37:05.426Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"5e87fd08fc96d0cd became follower at term 5"}
{"level":"info","ts":"2022-11-11T10:37:05.426Z","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"newRaft 5e87fd08fc96d0cd [peers: [], term: 5, commit: 683, applied: 0, lastindex: 684, lastterm: 5]"}
{"level":"warn","ts":1668163025.4271722,"caller":"fileutil/fileutil.go:57","msg":"check file permission","error":"directory \"/data/member\" exist, but the permission is \"dgrwxrwx---\". The recommended permission is \"-rwx------\" to prevent possible unprivileged access to the data"}
{"level":"warn","ts":"2022-11-11T10:37:05.429Z","caller":"auth/store.go:1220","msg":"simple token is not cryptographically signed"}
{"level":"info","ts":"2022-11-11T10:37:05.432Z","caller":"mvcc/kvstore.go:345","msg":"restored last compact revision","meta-bucket-name":"meta","meta-bucket-name-key":"finishedCompactRev","restored-compact-revision":406}
{"level":"info","ts":"2022-11-11T10:37:05.433Z","caller":"mvcc/kvstore.go:415","msg":"kvstore restored","current-rev":513}

[ahrtr]

Thanks @ankitg-03 for raising this issue. This seems like a good first issue for new contributors.

[ramil600]

This was reproduced in version v3.5.0. within function func TouchDirAll(dir string) error in client/pkg/fileutil/fileutil.go
The issue was that, it was creating new logger with default timestamp:

if err != nil {
			lg, _ := zap.NewProduction()
			if lg == nil {
				lg = zap.NewExample()
			}
			lg.Warn("check file permission", zap.Error(err))
		}

Since v 3.6.0 the reported issue was fixed. The signature of this function was changed to inject *zap.logger, and the issue is not reproducible anymore (it works fine):
func TouchDirAll(lg *zap.Logger, dir string) error

[halegreen]

working on this.

[ankitg-03]

Hi, I checked that the fix would be delivered in ETCD 3.5.6. Could you please share the timeline for release of 3.5.6?

[serathius]

Fixed with #14799

[ankitg-03]

Hi @serathius ,
First, I would like to thank you for providing the fix regarding the Inconsistent Timestamps in ETCD logs.

Could you please help to change the timestamp format as below.
Currently we get ETCD timestamps in the the following format - 2022-11-18T07:16:40.169Z but, our required format is 2022-11-18T07:15:24.722+02:00
Is there is a way to get timestamp in ETCD log in the required format 2022-11-18T07:15:24.722+02:00 ("yyyy-MM-dd'T'HH:mm:ss.SSSxxx") through some ETCD configuration?

Secondly, I would kindly like to ask you the timeline for release of 3.5.6?

[ankitg-03]

Hi @serathius ,
I wanted to follow up on the above mentioned query.

[serathius]

Don't know, please post questions on https://github.com/etcd-io/etcd/discussions

[ankitg-03]

Hi @ramil600
Could someone please look into the following query regarding the ETCD timestamp
#14836