Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix inconsistent log format #13864

Merged
merged 2 commits into from
Apr 1, 2022
Merged

Fix inconsistent log format #13864

merged 2 commits into from
Apr 1, 2022

Conversation

serathius
Copy link
Member

@serathius serathius commented Mar 31, 2022

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

@serathius serathius changed the title Fix invalid log format Fix inconsistent log format Mar 31, 2022
@codecov-commenter
Copy link

codecov-commenter commented Mar 31, 2022

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.

@@ -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()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do you prefer Nop ?

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

}

// 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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 Outdated Show resolved Hide resolved
This fixes problem where logs json changes format of timestamp.
@@ -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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

@ahrtr ahrtr left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@serathius serathius merged commit b161093 into etcd-io:main Apr 1, 2022
@tjungblu tjungblu mentioned this pull request Jul 27, 2022
@serathius serathius deleted the logs branch June 15, 2023 20:38
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants