From e5bf23037ab7ce9453bddade5d339da98724e296 Mon Sep 17 00:00:00 2001 From: Marek Siarkowicz Date: Thu, 31 Mar 2022 20:19:40 +0200 Subject: [PATCH 1/2] tests: Keeps log in expect to allow their analysis --- pkg/expect/expect.go | 59 +++++++++++++++++------------ tests/framework/e2e/etcd_process.go | 2 + tests/framework/e2e/util.go | 18 +++------ 3 files changed, 42 insertions(+), 37 deletions(-) diff --git a/pkg/expect/expect.go b/pkg/expect/expect.go index 3dcc6e8a2ad..31102c9c1a3 100644 --- a/pkg/expect/expect.go +++ b/pkg/expect/expect.go @@ -25,6 +25,7 @@ import ( "strings" "sync" "syscall" + "time" "github.com/creack/pty" ) @@ -36,7 +37,6 @@ type ExpectProcess struct { fpty *os.File wg sync.WaitGroup - cond *sync.Cond // for broadcasting updates are available mu sync.Mutex // protects lines and err lines []string count int // increment whenever new line gets added @@ -60,7 +60,6 @@ func NewExpectWithEnv(name string, args []string, env []string) (ep *ExpectProce cmd: cmd, StopSignal: syscall.SIGKILL, } - ep.cond = sync.NewCond(&ep.mu) ep.cmd.Stderr = ep.cmd.Stdout ep.cmd.Stdin = nil @@ -77,52 +76,56 @@ func (ep *ExpectProcess) read() { defer ep.wg.Done() printDebugLines := os.Getenv("EXPECT_DEBUG") != "" r := bufio.NewReader(ep.fpty) - for ep.err == nil { - l, rerr := r.ReadString('\n') + for { + l, err := r.ReadString('\n') ep.mu.Lock() - ep.err = rerr if l != "" { if printDebugLines { fmt.Printf("%s-%d: %s", ep.cmd.Path, ep.cmd.Process.Pid, l) } ep.lines = append(ep.lines, l) ep.count++ - if len(ep.lines) == 1 { - ep.cond.Signal() - } + } + if err != nil { + ep.err = err + ep.mu.Unlock() + break } ep.mu.Unlock() } - ep.cond.Signal() } // 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 - ep.mu.Lock() for { - for len(ep.lines) == 0 && ep.err == nil { - ep.cond.Wait() - } - if len(ep.lines) == 0 { - break - } - l := ep.lines[0] - ep.lines = ep.lines[1:] - lastLinesBuffer = append(lastLinesBuffer, l) - if l := len(lastLinesBuffer); l > DEBUG_LINES_TAIL { - lastLinesBuffer = lastLinesBuffer[l-DEBUG_LINES_TAIL : l-1] + ep.mu.Lock() + for i < len(ep.lines) { + line := ep.lines[i] + i++ + if f(line) { + ep.mu.Unlock() + return line, nil + } } - if f(l) { + if ep.err != nil { ep.mu.Unlock() - return l, nil + break } + ep.mu.Unlock() + time.Sleep(time.Millisecond * 100) + } + ep.mu.Lock() + lastLinesIndex := len(ep.lines) - DEBUG_LINES_TAIL + if lastLinesIndex < 0 { + lastLinesIndex = 0 } + lastLines := strings.Join(ep.lines[lastLinesIndex:], "") ep.mu.Unlock() return "", fmt.Errorf("match not found."+ " Set EXPECT_DEBUG for more info Err: %v, last lines:\n%s", - ep.err, strings.Join(lastLinesBuffer, "")) + ep.err, lastLines) } // Expect returns the first line containing the given string. @@ -189,3 +192,9 @@ func (ep *ExpectProcess) ProcessError() error { } return ep.err } + +func (ep *ExpectProcess) Lines() []string { + ep.mu.Lock() + defer ep.mu.Unlock() + return ep.lines +} diff --git a/tests/framework/e2e/etcd_process.go b/tests/framework/e2e/etcd_process.go index e31f906aeac..d80710c4048 100644 --- a/tests/framework/e2e/etcd_process.go +++ b/tests/framework/e2e/etcd_process.go @@ -48,6 +48,8 @@ type EtcdProcess interface { type LogsExpect interface { Expect(string) (string, error) + Lines() []string + LineCount() int } type EtcdServerProcess struct { diff --git a/tests/framework/e2e/util.go b/tests/framework/e2e/util.go index 7d997e08a92..6db4e404db8 100644 --- a/tests/framework/e2e/util.go +++ b/tests/framework/e2e/util.go @@ -61,21 +61,15 @@ func SpawnWithExpectLines(args []string, envVars map[string]string, xs ...string // process until either stdout or stderr contains // the expected string var ( - lines []string - lineFunc = func(txt string) bool { return true } + lines []string ) for _, txt := range xs { - for { - l, lerr := proc.ExpectFunc(lineFunc) - if lerr != nil { - proc.Close() - return nil, fmt.Errorf("%v %v (expected %q, got %q). Try EXPECT_DEBUG=TRUE", args, lerr, txt, lines) - } - lines = append(lines, l) - if strings.Contains(l, txt) { - break - } + l, lerr := proc.Expect(txt) + if lerr != nil { + proc.Close() + return nil, fmt.Errorf("%v %v (expected %q, got %q). Try EXPECT_DEBUG=TRUE", args, lerr, txt, lines) } + lines = append(lines, l) } perr := proc.Close() l := proc.LineCount() From 63346bfead7dd9ad071485d7cc7d6c8bd9fc36b7 Mon Sep 17 00:00:00 2001 From: Marek Siarkowicz Date: Thu, 31 Mar 2022 20:23:45 +0200 Subject: [PATCH 2/2] server: Use default logging configuration instead of zap production one This fixes problem where logs json changes format of timestamp. --- CHANGELOG/CHANGELOG-3.5.md | 1 + CHANGELOG/CHANGELOG-3.6.md | 1 + client/pkg/logutil/zap.go | 11 ++++ client/v3/client.go | 6 +- client/v3/logger.go | 22 +------ client/v3/snapshot/v3_snapshot.go | 3 - etcdctl/ctlv3/command/ep_command.go | 5 +- etcdctl/ctlv3/command/global.go | 7 +- etcdctl/ctlv3/command/snapshot_command.go | 3 +- etcdutl/etcdutl/common.go | 3 +- etcdutl/snapshot/v3_snapshot.go | 3 - pkg/netutil/netutil.go | 6 -- pkg/proxy/server.go | 12 ---- server/etcdmain/config.go | 3 +- server/etcdmain/etcd.go | 12 ++-- server/etcdmain/gateway.go | 4 +- server/etcdmain/grpc_proxy.go | 10 ++- server/etcdmain/main.go | 3 - tests/e2e/zap_logging_test.go | 78 +++++++++++++++++++++++ tests/framework/e2e/cluster.go | 5 ++ 20 files changed, 129 insertions(+), 69 deletions(-) create mode 100644 tests/e2e/zap_logging_test.go diff --git a/CHANGELOG/CHANGELOG-3.5.md b/CHANGELOG/CHANGELOG-3.5.md index 6bf16109d38..4e8477ad76f 100644 --- a/CHANGELOG/CHANGELOG-3.5.md +++ b/CHANGELOG/CHANGELOG-3.5.md @@ -11,6 +11,7 @@ The minimum recommended etcd versions to run in **production** are 3.3.18+, 3.4. ### etcd server - Fix [Provide a better liveness probe for when etcd runs as a Kubernetes pod](https://github.com/etcd-io/etcd/pull/13706) +- Fix [inconsistent log format](https://github.com/etcd-io/etcd/pull/13864) ### package `client/pkg/v3` diff --git a/CHANGELOG/CHANGELOG-3.6.md b/CHANGELOG/CHANGELOG-3.6.md index 9210d427f7c..383cf82e7f1 100644 --- a/CHANGELOG/CHANGELOG-3.6.md +++ b/CHANGELOG/CHANGELOG-3.6.md @@ -63,6 +63,7 @@ See [code changes](https://github.com/etcd-io/etcd/compare/v3.5.0...v3.6.0). - Fix [A client can cause a nil dereference in etcd by passing an invalid SortTarget](https://github.com/etcd-io/etcd/pull/13555) - Fix [Grant lease with negative ID can possibly cause db out of sync](https://github.com/etcd-io/etcd/pull/13676) - Fix [segmentation violation(SIGSEGV) error due to premature unlocking of watchableStore](https://github.com/etcd-io/etcd/pull/13505) +- Fix [inconsistent log format](https://github.com/etcd-io/etcd/pull/13864) ### tools/benchmark diff --git a/client/pkg/logutil/zap.go b/client/pkg/logutil/zap.go index 33d95e9cb17..0a4374c77b8 100644 --- a/client/pkg/logutil/zap.go +++ b/client/pkg/logutil/zap.go @@ -21,6 +21,17 @@ import ( "go.uber.org/zap/zapcore" ) +// CreateDefaultZapLogger creates a logger with default zap configuration +func CreateDefaultZapLogger(level zapcore.Level) (*zap.Logger, error) { + lcfg := DefaultZapLoggerConfig + lcfg.Level = zap.NewAtomicLevelAt(level) + c, err := lcfg.Build() + if err != nil { + return nil, err + } + return c, nil +} + // DefaultZapLoggerConfig defines default zap logger configuration. var DefaultZapLoggerConfig = zap.Config{ Level: zap.NewAtomicLevelAt(ConvertToZapLevel(DefaultLogLevel)), diff --git a/client/v3/client.go b/client/v3/client.go index 971fea607cf..91c091adfc9 100644 --- a/client/v3/client.go +++ b/client/v3/client.go @@ -24,6 +24,7 @@ import ( "time" "go.etcd.io/etcd/api/v3/v3rpc/rpctypes" + "go.etcd.io/etcd/client/pkg/v3/logutil" "go.etcd.io/etcd/client/v3/credentials" "go.etcd.io/etcd/client/v3/internal/endpoint" "go.etcd.io/etcd/client/v3/internal/resolver" @@ -370,7 +371,10 @@ func newClient(cfg *Config) (*Client, error) { } else if cfg.LogConfig != nil { client.lg, err = cfg.LogConfig.Build() } else { - client.lg, err = CreateDefaultZapLogger() + client.lg, err = logutil.CreateDefaultZapLogger(etcdClientDebugLevel()) + if client.lg != nil { + client.lg = client.lg.Named("etcd-client") + } } if err != nil { return nil, err diff --git a/client/v3/logger.go b/client/v3/logger.go index 71a9e161ce8..ecac42730f6 100644 --- a/client/v3/logger.go +++ b/client/v3/logger.go @@ -19,7 +19,6 @@ import ( "os" "go.etcd.io/etcd/client/pkg/v3/logutil" - "go.uber.org/zap" "go.uber.org/zap/zapcore" "go.uber.org/zap/zapgrpc" "google.golang.org/grpc/grpclog" @@ -29,10 +28,11 @@ func init() { // We override grpc logger only when the environment variable is set // in order to not interfere by default with user's code or other libraries. if os.Getenv("ETCD_CLIENT_DEBUG") != "" { - lg, err := CreateDefaultZapLogger() + lg, err := logutil.CreateDefaultZapLogger(etcdClientDebugLevel()) if err != nil { panic(err) } + lg = lg.Named("etcd-client") grpclog.SetLoggerV2(zapgrpc.NewLogger(lg)) } } @@ -57,21 +57,3 @@ func etcdClientDebugLevel() zapcore.Level { } return l } - -// CreateDefaultZapLoggerConfig creates a logger config that is configurable using env variable: -// ETCD_CLIENT_DEBUG= debug|info|warn|error|dpanic|panic|fatal|true (true=info) -func CreateDefaultZapLoggerConfig() zap.Config { - lcfg := logutil.DefaultZapLoggerConfig - lcfg.Level = zap.NewAtomicLevelAt(etcdClientDebugLevel()) - return lcfg -} - -// CreateDefaultZapLogger creates a logger that is configurable using env variable: -// ETCD_CLIENT_DEBUG= debug|info|warn|error|dpanic|panic|fatal|true (true=info) -func CreateDefaultZapLogger() (*zap.Logger, error) { - c, err := CreateDefaultZapLoggerConfig().Build() - if err != nil { - return nil, err - } - return c.Named("etcd-client"), nil -} diff --git a/client/v3/snapshot/v3_snapshot.go b/client/v3/snapshot/v3_snapshot.go index d5a8c268288..3ad13cf4cbe 100644 --- a/client/v3/snapshot/v3_snapshot.go +++ b/client/v3/snapshot/v3_snapshot.go @@ -45,9 +45,6 @@ func hasChecksum(n int64) bool { // the selected node. // Etcd