From d72f7ef5cc4f09a270438c40e8c32e5280e96965 Mon Sep 17 00:00:00 2001 From: Piotr Tabor Date: Wed, 14 Apr 2021 12:16:11 +0200 Subject: [PATCH] Give control to Embedded servers whether they override global loggers So far each instance of embed server was overriding the grpc loggers and zap.global loggers. It's counter intutitive that last created Embedded server was 'wining' and more-over it was breaking grpc expectation to change it "only" before the grpc stack is being used. This PR introduces explicit call: `embed.Config::SetupGlobalLoggers()`, that changes the loggers where requested. The call is used by etcd main binary. The immediate benefit from this change is reduction of test flakiness, as there were flakes due to not a proper logger being used across tests. --- CHANGELOG-3.5.md | 1 + server/embed/config_logging.go | 76 ++++++------------- server/etcdmain/etcd.go | 2 + tests/integration/main_test.go | 2 - .../integration/snapshot/v3_snapshot_test.go | 4 +- tests/integration/testing.go | 8 +- 6 files changed, 33 insertions(+), 60 deletions(-) diff --git a/CHANGELOG-3.5.md b/CHANGELOG-3.5.md index aa052fa30..1a875e8f6 100644 --- a/CHANGELOG-3.5.md +++ b/CHANGELOG-3.5.md @@ -69,6 +69,7 @@ See [code changes](https://github.com/etcd-io/etcd/compare/v3.4.0...v3.5.0) and - Turned on [--pre-vote by default](https://github.com/etcd-io/etcd/pull/12770). Should prevent disrupting RAFT leader by an individual member. - [ETCD_CLIENT_DEBUG env](https://github.com/etcd-io/etcd/pull/12786): Now supports log levels (debug, info, warn, error, dpanic, panic, fatal). Only when set, overrides application-wide grpc logging settings. - [Embed Etcd.Close()](https://github.com/etcd-io/etcd/pull/12828) needs to called exactly once and closes Etcd.Err() stream. +- [Embed Etcd does not override global/grpc logger](https://github.com/etcd-io/etcd/pull/12861) be default any longer. If desired, please call `embed.Config::SetupGlobalLoggers()` explicitly. ### - Make sure [save snapshot downloads checksum for integrity checks](https://github.com/etcd-io/etcd/pull/11896). diff --git a/server/embed/config_logging.go b/server/embed/config_logging.go index 9306c9199..360cdde80 100644 --- a/server/embed/config_logging.go +++ b/server/embed/config_logging.go @@ -19,15 +19,14 @@ import ( "fmt" "io/ioutil" "os" - "sync" - grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap" "go.etcd.io/etcd/client/pkg/v3/logutil" + "go.uber.org/zap/zapgrpc" + "google.golang.org/grpc/grpclog" "go.uber.org/zap" "go.uber.org/zap/zapcore" "google.golang.org/grpc" - "google.golang.org/grpc/grpclog" ) // GetLogger returns the logger. @@ -38,29 +37,6 @@ func (cfg Config) GetLogger() *zap.Logger { return l } -// for testing -var grpcLogOnce = new(sync.Once) - -func setupGrpcLogging(debug bool, config zap.Config) { - grpcLogOnce.Do(func() { - // debug true, enable info, warning, error - // debug false, only discard info - if debug { - var gl grpclog.LoggerV2 - gl, err := logutil.NewGRPCLoggerV2(config) - if err == nil { - grpclog.SetLoggerV2(gl) - } - } else { - grpclog.SetLoggerV2(grpclog.NewLoggerV2(ioutil.Discard, os.Stderr, os.Stderr)) - } - }) -} - -func SetupGrpcLoggingForTest(debug bool) { - setupGrpcLogging(debug, zap.NewDevelopmentConfig()) -} - // setupLogging initializes etcd logging. // Must be called after flag parsing or finishing configuring embed.Config. func (cfg *Config) setupLogging() error { @@ -111,9 +87,6 @@ func (cfg *Config) setupLogging() error { copied.ErrorOutputPaths = errOutputPaths copied = logutil.MergeOutputPaths(copied) copied.Level = zap.NewAtomicLevelAt(logutil.ConvertToZapLevel(cfg.LogLevel)) - if cfg.LogLevel == "debug" { - grpc.EnableTracing = true - } if cfg.ZapLoggerBuilder == nil { cfg.ZapLoggerBuilder = func(c *Config) error { var err error @@ -121,13 +94,11 @@ func (cfg *Config) setupLogging() error { if err != nil { return err } - zap.ReplaceGlobals(c.logger) c.loggerMu.Lock() defer c.loggerMu.Unlock() c.loggerConfig = &copied c.loggerCore = nil c.loggerWriteSyncer = nil - setupGrpcLogging(cfg.LogLevel == "debug", copied) return nil } } @@ -147,9 +118,6 @@ func (cfg *Config) setupLogging() error { } lvl := zap.NewAtomicLevelAt(logutil.ConvertToZapLevel(cfg.LogLevel)) - if cfg.LogLevel == "debug" { - grpc.EnableTracing = true - } // WARN: do not change field names in encoder config // journald logging writer assumes field names of "level" and "caller" @@ -161,20 +129,12 @@ func (cfg *Config) setupLogging() error { if cfg.ZapLoggerBuilder == nil { cfg.ZapLoggerBuilder = func(c *Config) error { c.logger = zap.New(cr, zap.AddCaller(), zap.ErrorOutput(syncer)) - zap.ReplaceGlobals(c.logger) c.loggerMu.Lock() defer c.loggerMu.Unlock() c.loggerConfig = nil c.loggerCore = cr c.loggerWriteSyncer = syncer - grpcLogOnce.Do(func() { - if cfg.LogLevel == "debug" { - grpclog.SetLoggerV2(logutil.NewGRPCLoggerV2FromZapCore(cr, syncer)) - } else { - grpclog.SetLoggerV2(grpclog.NewLoggerV2(ioutil.Discard, os.Stderr, os.Stderr)) - } - }) return nil } } @@ -223,22 +183,32 @@ func (cfg *Config) setupLogging() error { } // NewZapCoreLoggerBuilder generates a zap core logger builder. -func NewZapCoreLoggerBuilder(lg *zap.Logger, cr zapcore.Core, syncer zapcore.WriteSyncer) func(*Config) error { +func NewZapCoreLoggerBuilder(lg *zap.Logger) func(*Config) error { return func(cfg *Config) error { cfg.loggerMu.Lock() defer cfg.loggerMu.Unlock() cfg.logger = lg cfg.loggerConfig = nil - cfg.loggerCore = cr - cfg.loggerWriteSyncer = syncer - - grpcLogOnce.Do(func() { - if cr != nil && syncer != nil { - grpclog.SetLoggerV2(logutil.NewGRPCLoggerV2FromZapCore(cr, syncer)) - } else { - grpc_zap.ReplaceGrpcLoggerV2(cfg.logger.Named("grpc")) - } - }) + cfg.loggerCore = nil + cfg.loggerWriteSyncer = nil return nil } } + +// SetupGlobalLoggers configures 'global' loggers (grpc, zapGlobal) based on the cfg. +// +// The method is not executed by embed server by default (since 3.5) to +// enable setups where grpc/zap.Global logging is configured independently +// or spans separate lifecycle (like in tests). +func (cfg *Config) SetupGlobalLoggers() { + lg := cfg.GetLogger() + if lg != nil { + if cfg.LogLevel == "debug" { + grpc.EnableTracing = true + grpclog.SetLoggerV2(zapgrpc.NewLogger(lg)) + } else { + grpclog.SetLoggerV2(grpclog.NewLoggerV2(ioutil.Discard, os.Stderr, os.Stderr)) + } + zap.ReplaceGlobals(lg) + } +} diff --git a/server/etcdmain/etcd.go b/server/etcdmain/etcd.go index a7a02bc50..ab64afaeb 100644 --- a/server/etcdmain/etcd.go +++ b/server/etcdmain/etcd.go @@ -57,6 +57,8 @@ func startEtcdOrProxyV2(args []string) { err := cfg.parse(args[1:]) lg := cfg.ec.GetLogger() + cfg.ec.SetupGlobalLoggers() + if lg == nil { var zapError error // use this logger diff --git a/tests/integration/main_test.go b/tests/integration/main_test.go index 60c6d7b60..e78320583 100644 --- a/tests/integration/main_test.go +++ b/tests/integration/main_test.go @@ -8,10 +8,8 @@ import ( "testing" "go.etcd.io/etcd/client/pkg/v3/testutil" - "go.etcd.io/etcd/server/v3/embed" ) func TestMain(m *testing.M) { - embed.SetupGrpcLoggingForTest(true) testutil.MustTestMainWithLeakDetection(m) } diff --git a/tests/integration/snapshot/v3_snapshot_test.go b/tests/integration/snapshot/v3_snapshot_test.go index 145f47a72..c0df2e48c 100644 --- a/tests/integration/snapshot/v3_snapshot_test.go +++ b/tests/integration/snapshot/v3_snapshot_test.go @@ -230,13 +230,13 @@ func restoreCluster(t *testing.T, clusterN int, dbPath string) ( ics := "" for i := 0; i < clusterN; i++ { - ics += fmt.Sprintf(",%d=%s", i, pURLs[i].String()) + ics += fmt.Sprintf(",m%d=%s", i, pURLs[i].String()) } ics = ics[1:] cfgs := make([]*embed.Config, clusterN) for i := 0; i < clusterN; i++ { - cfg := integration.NewEmbedConfig(t, fmt.Sprintf("%d", i)) + cfg := integration.NewEmbedConfig(t, fmt.Sprintf("m%d", i)) cfg.InitialClusterToken = testClusterTkn cfg.ClusterState = "existing" cfg.LCUrls, cfg.ACUrls = []url.URL{cURLs[i]}, []url.URL{cURLs[i]} diff --git a/tests/integration/testing.go b/tests/integration/testing.go index 345e4da63..df7b3dd1f 100644 --- a/tests/integration/testing.go +++ b/tests/integration/testing.go @@ -20,9 +20,10 @@ import ( "testing" grpc_logsettable "github.com/grpc-ecosystem/go-grpc-middleware/logging/settable" - grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap" "go.etcd.io/etcd/client/pkg/v3/testutil" "go.etcd.io/etcd/server/v3/embed" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zapgrpc" "go.uber.org/zap/zaptest" ) @@ -35,7 +36,7 @@ func init() { func BeforeTest(t testutil.TB) { testutil.BeforeTest(t) - grpc_zap.SetGrpcLoggerV2(grpc_logger, zaptest.NewLogger(t).Named("grpc")) + grpc_logger.Set(zapgrpc.NewLogger(zaptest.NewLogger(t).Named("grpc"))) previousWD, err := os.Getwd() if err != nil { @@ -60,7 +61,8 @@ func MustAbsPath(path string) string { func NewEmbedConfig(t testing.TB, name string) *embed.Config { cfg := embed.NewConfig() cfg.Name = name - cfg.ZapLoggerBuilder = embed.NewZapCoreLoggerBuilder(zaptest.NewLogger(t).Named(cfg.Name), nil, nil) + lg := zaptest.NewLogger(t, zaptest.Level(zapcore.InfoLevel)).Named(cfg.Name) + cfg.ZapLoggerBuilder = embed.NewZapCoreLoggerBuilder(lg) cfg.Dir = t.TempDir() return cfg }