diff --git a/CHANGELOG/CHANGELOG-3.5.md b/CHANGELOG/CHANGELOG-3.5.md index 7d2038813..b075d04d5 100644 --- a/CHANGELOG/CHANGELOG-3.5.md +++ b/CHANGELOG/CHANGELOG-3.5.md @@ -9,6 +9,7 @@ Previous change logs can be found at [CHANGELOG-3.4](https://github.com/etcd-io/ ### 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 9210d427f..383cf82e7 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 33d95e9cb..0a4374c77 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 971fea607..91c091adf 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 71a9e161c..ecac42730 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 d5a8c2682..3ad13cf4c 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 DEBUG_LINES_TAIL { - lastLinesBuffer = lastLinesBuffer[l-DEBUG_LINES_TAIL : l-1] - } - if f(l) { - ep.mu.Unlock() - return l, nil - } + 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/pkg/netutil/netutil.go b/pkg/netutil/netutil.go index 43c93ba3c..2f3558995 100644 --- a/pkg/netutil/netutil.go +++ b/pkg/netutil/netutil.go @@ -193,12 +193,6 @@ func URLStringsEqual(ctx context.Context, lg *zap.Logger, a []string, b []string if err != nil { return false, err } - if lg == nil { - lg, _ = zap.NewProduction() - if lg == nil { - lg = zap.NewExample() - } - } return urlsEqual(ctx, lg, urlsA, urlsB) } diff --git a/pkg/proxy/server.go b/pkg/proxy/server.go index 9a7b105f9..72a0c7483 100644 --- a/pkg/proxy/server.go +++ b/pkg/proxy/server.go @@ -37,17 +37,8 @@ var ( defaultDialTimeout = 3 * time.Second defaultBufferSize = 48 * 1024 defaultRetryInterval = 10 * time.Millisecond - defaultLogger *zap.Logger ) -func init() { - var err error - defaultLogger, err = zap.NewProduction() - if err != nil { - panic(err) - } -} - // Server defines proxy server layer that simulates common network faults: // latency spikes and packet drop or corruption. The proxy overhead is very // small overhead (<500μs per request). Please run tests to compute actual @@ -240,9 +231,6 @@ func NewServer(cfg ServerConfig) Server { if s.retryInterval == 0 { s.retryInterval = defaultRetryInterval } - if s.lg == nil { - s.lg = defaultLogger - } close(s.pauseAcceptc) close(s.pauseTxc) diff --git a/server/etcdmain/config.go b/server/etcdmain/config.go index 71a776373..2206ce001 100644 --- a/server/etcdmain/config.go +++ b/server/etcdmain/config.go @@ -377,11 +377,10 @@ func (cfg *config) parse(arguments []string) error { func (cfg *config) configFromCmdLine() error { // user-specified logger is not setup yet, use this logger during flag parsing - lg, err := zap.NewProduction() + lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel) if err != nil { return err } - verKey := "ETCD_VERSION" if verVal := os.Getenv(verKey); verVal != "" { // unset to avoid any possible side-effect. diff --git a/server/etcdmain/etcd.go b/server/etcdmain/etcd.go index 4618d40fe..69828c5fd 100644 --- a/server/etcdmain/etcd.go +++ b/server/etcdmain/etcd.go @@ -17,7 +17,6 @@ package etcdmain import ( "encoding/json" "fmt" - "net/http" "os" "path/filepath" @@ -27,6 +26,7 @@ import ( "time" "go.etcd.io/etcd/client/pkg/v3/fileutil" + "go.etcd.io/etcd/client/pkg/v3/logutil" "go.etcd.io/etcd/client/pkg/v3/transport" "go.etcd.io/etcd/client/pkg/v3/types" pkgioutil "go.etcd.io/etcd/pkg/v3/ioutil" @@ -64,7 +64,7 @@ func startEtcdOrProxyV2(args []string) { if lg == nil { var zapError error // use this logger - lg, zapError = zap.NewProduction() + lg, zapError = logutil.CreateDefaultZapLogger(zap.InfoLevel) if zapError != nil { fmt.Printf("error creating zap logger %v", zapError) os.Exit(1) @@ -470,6 +470,10 @@ func identifyDataDirOrDie(lg *zap.Logger, dir string) dirType { } func checkSupportArch() { + lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel) + if err != nil { + panic(err) + } // to add a new platform, check https://github.com/etcd-io/website/blob/main/content/en/docs/next/op-guide/supported-platform.md if runtime.GOARCH == "amd64" || runtime.GOARCH == "arm64" || @@ -481,10 +485,10 @@ func checkSupportArch() { // so unset here to not parse through flag defer os.Unsetenv("ETCD_UNSUPPORTED_ARCH") if env, ok := os.LookupEnv("ETCD_UNSUPPORTED_ARCH"); ok && env == runtime.GOARCH { - fmt.Printf("running etcd on unsupported architecture %q since ETCD_UNSUPPORTED_ARCH is set\n", env) + lg.Info("running etcd on unsupported architecture since ETCD_UNSUPPORTED_ARCH is set", zap.String("arch", env)) return } - fmt.Printf("etcd on unsupported platform without ETCD_UNSUPPORTED_ARCH=%s set\n", runtime.GOARCH) + lg.Error("running etcd on unsupported architecture since ETCD_UNSUPPORTED_ARCH is set", zap.String("arch", runtime.GOARCH)) os.Exit(1) } diff --git a/server/etcdmain/gateway.go b/server/etcdmain/gateway.go index 3e4d0620c..64fb90df2 100644 --- a/server/etcdmain/gateway.go +++ b/server/etcdmain/gateway.go @@ -21,6 +21,7 @@ import ( "os" "time" + "go.etcd.io/etcd/client/pkg/v3/logutil" "go.etcd.io/etcd/server/v3/proxy/tcpproxy" "github.com/spf13/cobra" @@ -92,8 +93,7 @@ func stripSchema(eps []string) []string { } func startGateway(cmd *cobra.Command, args []string) { - var lg *zap.Logger - lg, err := zap.NewProduction() + lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel) if err != nil { fmt.Fprintln(os.Stderr, err) os.Exit(1) diff --git a/server/etcdmain/grpc_proxy.go b/server/etcdmain/grpc_proxy.go index f850f915f..55cc96d0c 100644 --- a/server/etcdmain/grpc_proxy.go +++ b/server/etcdmain/grpc_proxy.go @@ -164,16 +164,14 @@ func newGRPCProxyStartCommand() *cobra.Command { func startGRPCProxy(cmd *cobra.Command, args []string) { checkArgs() - - lcfg := logutil.DefaultZapLoggerConfig + lvl := zap.InfoLevel if grpcProxyDebug { - lcfg.Level = zap.NewAtomicLevelAt(zap.DebugLevel) + lvl = zap.DebugLevel grpc.EnableTracing = true } - - lg, err := lcfg.Build() + lg, err := logutil.CreateDefaultZapLogger(lvl) if err != nil { - log.Fatal(err) + panic(err) } defer lg.Sync() diff --git a/server/etcdmain/main.go b/server/etcdmain/main.go index 2e67a137c..e28e7da92 100644 --- a/server/etcdmain/main.go +++ b/server/etcdmain/main.go @@ -41,9 +41,6 @@ func Main(args []string) { } func notifySystemd(lg *zap.Logger) { - if lg == nil { - lg = zap.NewExample() - } lg.Info("notifying init daemon") _, err := daemon.SdNotify(false, daemon.SdNotifyReady) if err != nil { diff --git a/tests/e2e/zap_logging_test.go b/tests/e2e/zap_logging_test.go new file mode 100644 index 000000000..ef37ef79b --- /dev/null +++ b/tests/e2e/zap_logging_test.go @@ -0,0 +1,78 @@ +// Copyright 2022 The etcd Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +//go:build !cov +// +build !cov + +package e2e + +import ( + "encoding/json" + "testing" + "time" + + "go.etcd.io/etcd/tests/v3/framework/e2e" +) + +func TestServerJsonLogging(t *testing.T) { + e2e.BeforeTest(t) + + epc, err := e2e.NewEtcdProcessCluster(t, &e2e.EtcdProcessClusterConfig{ + ClusterSize: 1, + InitialToken: "new", + LogLevel: "debug", + }) + if err != nil { + t.Fatalf("could not start etcd process cluster (%v)", err) + } + logs := epc.Procs[0].Logs() + time.Sleep(time.Second) + if err = epc.Close(); err != nil { + t.Fatalf("error closing etcd processes (%v)", err) + } + var entry logEntry + lines := logs.Lines() + if len(lines) == 0 { + t.Errorf("Expected at least one log line") + } + for _, line := range lines { + err := json.Unmarshal([]byte(line), &entry) + if err != nil { + t.Errorf("Failed to parse log line as json, err: %q, line: %s", err, line) + continue + } + if entry.Level == "" { + t.Errorf(`Missing "level" key, line: %s`, line) + } + if entry.Timestamp == "" { + t.Errorf(`Missing "ts" key, line: %s`, line) + } + if _, err := time.Parse("2006-01-02T15:04:05.000Z0700", entry.Timestamp); entry.Timestamp != "" && err != nil { + t.Errorf(`Unexpected "ts" key format, err: %s`, err) + } + if entry.Caller == "" { + t.Errorf(`Missing "caller" key, line: %s`, line) + } + if entry.Message == "" { + t.Errorf(`Missing "message" key, line: %s`, line) + } + } +} + +type logEntry struct { + Level string `json:"level"` + Timestamp string `json:"ts"` + Caller string `json:"caller"` + Message string `json:"msg"` +} diff --git a/tests/framework/e2e/cluster.go b/tests/framework/e2e/cluster.go index 64be2f39c..4b1daf93d 100644 --- a/tests/framework/e2e/cluster.go +++ b/tests/framework/e2e/cluster.go @@ -175,6 +175,7 @@ type EtcdProcessClusterConfig struct { DiscoveryEndpoints []string // v3 discovery DiscoveryToken string + LogLevel string } // NewEtcdProcessCluster launches a new cluster from etcd processes, returning @@ -336,6 +337,10 @@ func (cfg *EtcdProcessClusterConfig) EtcdServerProcessConfigs(tb testing.TB) []* args = append(args, "--discovery", cfg.Discovery) } + if cfg.LogLevel != "" { + args = append(args, "--log-level", cfg.LogLevel) + } + etcdCfgs[i] = &EtcdServerProcessConfig{ lg: lg, ExecPath: cfg.ExecPath, diff --git a/tests/framework/e2e/etcd_process.go b/tests/framework/e2e/etcd_process.go index e31f906ae..d80710c40 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 7d997e08a..6db4e404d 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()