Fix inconsistent log format #13864

serathius · 2022-03-31T18:41:49Z

Found that etcd logs have inconsistent format. Logs written before etcd logger is configured will use a zap production configuration. This is a big problem when you try to parse those logs and notice that timestamp stored under ts key can change it's format from float to string.

Example logs:

{"level":"warn","ts":1648751556.7524385,"caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_UNSUPPORTED_ARCH=amd64"}
{"level":"warn","ts":1648751556.7524884,"caller":"flags/flag.go:93","msg":"unrecognized environment variable","environment-variable":"ETCD_VERIFY=all"}
{"level":"info","ts":"2022-03-31T20:32:36.752+0200","caller":"etcdmain/etcd.go:73","msg":"Running: ","args":["/home/serathius/src/go.etcd.io/etcd/bin/etcd","--name","test-0","--listen-client-urls","http://localhost:20000","--advertise-client-urls","http://localhost:20000","--listen-peer-urls","http://localhost:20001","--initial-advertise-peer-urls","http://localhost:20001","--initial-cluster-token","new","--data-dir","/tmp/TestServerJsonLogging3892089350/002","--snapshot-count","100000","--initial-cluster","test-0=http://localhost:20001"]}

cc @ahrtr @ptabor

codecov-commenter · 2022-03-31T20:54:24Z

Codecov Report

Merging #13864 (39949cc) into main (27e222e) will decrease coverage by 0.09%.
The diff coverage is 64.91%.

❗ Current head 39949cc differs from pull request most recent head f7d1de2. Consider uploading reports for the commit f7d1de2 to get more accurate results

@@            Coverage Diff             @@
##             main   #13864      +/-   ##
==========================================
- Coverage   72.51%   72.42%   -0.10%     
==========================================
  Files         468      467       -1     
  Lines       38222    38231       +9     
==========================================
- Hits        27718    27689      -29     
- Misses       8718     8752      +34     
- Partials     1786     1790       +4

Flag	Coverage Δ
all	`72.42% <64.91%> (-0.10%)`	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
client/v3/logger.go	`27.77% <0.00%> (-18.38%)`	⬇️
client/v3/snapshot/v3_snapshot.go	`52.08% <0.00%> (ø)`
etcdutl/snapshot/v3_snapshot.go	`65.54% <0.00%> (ø)`
pkg/netutil/netutil.go	`69.29% <0.00%> (+1.07%)`	⬆️
pkg/proxy/server.go	`60.81% <0.00%> (+<0.01%)`	⬆️
server/etcdmain/gateway.go	`24.70% <0.00%> (+0.28%)`	⬆️
server/etcdmain/main.go	`55.00% <0.00%> (ø)`
server/etcdmain/etcd.go	`45.36% <16.66%> (-0.12%)`	⬇️
etcdctl/ctlv3/command/ep_command.go	`45.97% <50.00%> (ø)`
server/etcdmain/grpc_proxy.go	`58.88% <50.00%> (ø)`
... and 36 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 27e222e...f7d1de2. Read the comment docs.

ptabor · 2022-04-01T07:05:12Z

client/v3/snapshot/v3_snapshot.go

@@ -46,7 +46,7 @@ func hasChecksum(n int64) bool {
 // Etcd <v3.6 will return "" as version.
 func SaveWithVersion(ctx context.Context, lg *zap.Logger, cfg clientv3.Config, dbPath string) (version string, err error) {
 	if lg == nil {
-		lg = zap.NewExample()
+		lg = zap.NewNop()


Why do you prefer Nop ?

Please add a comment, otherwise it's tempting during debugging to add back 'any logging'.

This is based on "no logging is better than inconsistent one. Alternatively I can remove the nil check.

ptabor · 2022-04-01T07:09:49Z

pkg/expect/expect.go

 }

 // ExpectFunc returns the first line satisfying the function f.
 func (ep *ExpectProcess) ExpectFunc(f func(string) bool) (string, error) {
-	lastLinesBuffer := make([]string, 0)
+	i := 0


This seems to be an orthogonal refactor on top of the logs change. What's the goal ?

This change is needed to write an e2e test that will scan all the logs and check if they all follow a single format.

pkg/netutil/netutil.go

This fixes problem where logs json changes format of timestamp.

ahrtr · 2022-04-01T08:31:36Z

etcdctl/ctlv3/command/ep_command.go

@@ -88,7 +89,7 @@ type epHealth struct {

 // epHealthCommandFunc executes the "endpoint-health" command.
 func epHealthCommandFunc(cmd *cobra.Command, args []string) {
-	lg, err := zap.NewProduction()
+	lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)


why not use etcdClientDebugLevel() here? I see other places all use it.

Got it, it's in different package client/v3

etcdClientDebugLevel is only used by etcd client in client/v3 package. The default verbosity for zap.NewProduction and zap.NewExample is info. I didn't want this PR to make any changes as this is a fix that I plan to backport to v3.5

ahrtr

LGTM

serathius force-pushed the logs branch from b8d3bd5 to e88caa9 Compare March 31, 2022 18:46

tests: Keeps log in expect to allow their analysis

e5bf230

serathius force-pushed the logs branch 5 times, most recently from 1253a9a to 5da0859 Compare March 31, 2022 19:59

serathius changed the title ~~Fix invalid log format~~ Fix inconsistent log format Mar 31, 2022

serathius force-pushed the logs branch from 5da0859 to f7d1de2 Compare March 31, 2022 20:11

ptabor approved these changes Apr 1, 2022

View reviewed changes

server: Use default logging configuration instead of zap production one

63346bf

This fixes problem where logs json changes format of timestamp.

serathius force-pushed the logs branch from f7d1de2 to 63346bf Compare April 1, 2022 08:23

ahrtr reviewed Apr 1, 2022

View reviewed changes

ahrtr approved these changes Apr 1, 2022

View reviewed changes

serathius merged commit b161093 into etcd-io:main Apr 1, 2022

serathius mentioned this pull request Apr 1, 2022

[release-3.5] Fix inconsistent log format #13866

Merged

tjungblu mentioned this pull request Jul 27, 2022

FLAKE: TestKVDelete #14275

Closed

serathius deleted the logs branch June 15, 2023 20:38

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix inconsistent log format #13864

Fix inconsistent log format #13864

serathius commented Mar 31, 2022 •

edited

Loading

codecov-commenter commented Mar 31, 2022 •

edited

Loading

ptabor Apr 1, 2022

serathius Apr 1, 2022

ptabor Apr 1, 2022

serathius Apr 1, 2022

ahrtr Apr 1, 2022

ahrtr Apr 1, 2022

serathius Apr 1, 2022

ahrtr left a comment

Fix inconsistent log format #13864

Fix inconsistent log format #13864

Conversation

serathius commented Mar 31, 2022 • edited Loading

codecov-commenter commented Mar 31, 2022 • edited Loading

Codecov Report

ptabor Apr 1, 2022

Choose a reason for hiding this comment

serathius Apr 1, 2022

Choose a reason for hiding this comment

ptabor Apr 1, 2022

Choose a reason for hiding this comment

serathius Apr 1, 2022

Choose a reason for hiding this comment

ahrtr Apr 1, 2022

Choose a reason for hiding this comment

ahrtr Apr 1, 2022

Choose a reason for hiding this comment

serathius Apr 1, 2022

Choose a reason for hiding this comment

ahrtr left a comment

Choose a reason for hiding this comment

serathius commented Mar 31, 2022 •

edited

Loading

codecov-commenter commented Mar 31, 2022 •

edited

Loading