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.
This commit is contained in:
Piotr Tabor 2021-04-14 12:16:11 +02:00
parent eafbc8c57e
commit d72f7ef5cc
6 changed files with 33 additions and 60 deletions

View File

@ -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. - 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. - [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.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). - Make sure [save snapshot downloads checksum for integrity checks](https://github.com/etcd-io/etcd/pull/11896).

View File

@ -19,15 +19,14 @@ import (
"fmt" "fmt"
"io/ioutil" "io/ioutil"
"os" "os"
"sync"
grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
"go.etcd.io/etcd/client/pkg/v3/logutil" "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"
"go.uber.org/zap/zapcore" "go.uber.org/zap/zapcore"
"google.golang.org/grpc" "google.golang.org/grpc"
"google.golang.org/grpc/grpclog"
) )
// GetLogger returns the logger. // GetLogger returns the logger.
@ -38,29 +37,6 @@ func (cfg Config) GetLogger() *zap.Logger {
return l 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. // setupLogging initializes etcd logging.
// Must be called after flag parsing or finishing configuring embed.Config. // Must be called after flag parsing or finishing configuring embed.Config.
func (cfg *Config) setupLogging() error { func (cfg *Config) setupLogging() error {
@ -111,9 +87,6 @@ func (cfg *Config) setupLogging() error {
copied.ErrorOutputPaths = errOutputPaths copied.ErrorOutputPaths = errOutputPaths
copied = logutil.MergeOutputPaths(copied) copied = logutil.MergeOutputPaths(copied)
copied.Level = zap.NewAtomicLevelAt(logutil.ConvertToZapLevel(cfg.LogLevel)) copied.Level = zap.NewAtomicLevelAt(logutil.ConvertToZapLevel(cfg.LogLevel))
if cfg.LogLevel == "debug" {
grpc.EnableTracing = true
}
if cfg.ZapLoggerBuilder == nil { if cfg.ZapLoggerBuilder == nil {
cfg.ZapLoggerBuilder = func(c *Config) error { cfg.ZapLoggerBuilder = func(c *Config) error {
var err error var err error
@ -121,13 +94,11 @@ func (cfg *Config) setupLogging() error {
if err != nil { if err != nil {
return err return err
} }
zap.ReplaceGlobals(c.logger)
c.loggerMu.Lock() c.loggerMu.Lock()
defer c.loggerMu.Unlock() defer c.loggerMu.Unlock()
c.loggerConfig = &copied c.loggerConfig = &copied
c.loggerCore = nil c.loggerCore = nil
c.loggerWriteSyncer = nil c.loggerWriteSyncer = nil
setupGrpcLogging(cfg.LogLevel == "debug", copied)
return nil return nil
} }
} }
@ -147,9 +118,6 @@ func (cfg *Config) setupLogging() error {
} }
lvl := zap.NewAtomicLevelAt(logutil.ConvertToZapLevel(cfg.LogLevel)) lvl := zap.NewAtomicLevelAt(logutil.ConvertToZapLevel(cfg.LogLevel))
if cfg.LogLevel == "debug" {
grpc.EnableTracing = true
}
// WARN: do not change field names in encoder config // WARN: do not change field names in encoder config
// journald logging writer assumes field names of "level" and "caller" // journald logging writer assumes field names of "level" and "caller"
@ -161,20 +129,12 @@ func (cfg *Config) setupLogging() error {
if cfg.ZapLoggerBuilder == nil { if cfg.ZapLoggerBuilder == nil {
cfg.ZapLoggerBuilder = func(c *Config) error { cfg.ZapLoggerBuilder = func(c *Config) error {
c.logger = zap.New(cr, zap.AddCaller(), zap.ErrorOutput(syncer)) c.logger = zap.New(cr, zap.AddCaller(), zap.ErrorOutput(syncer))
zap.ReplaceGlobals(c.logger)
c.loggerMu.Lock() c.loggerMu.Lock()
defer c.loggerMu.Unlock() defer c.loggerMu.Unlock()
c.loggerConfig = nil c.loggerConfig = nil
c.loggerCore = cr c.loggerCore = cr
c.loggerWriteSyncer = syncer 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 return nil
} }
} }
@ -223,22 +183,32 @@ func (cfg *Config) setupLogging() error {
} }
// NewZapCoreLoggerBuilder generates a zap core logger builder. // 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 { return func(cfg *Config) error {
cfg.loggerMu.Lock() cfg.loggerMu.Lock()
defer cfg.loggerMu.Unlock() defer cfg.loggerMu.Unlock()
cfg.logger = lg cfg.logger = lg
cfg.loggerConfig = nil cfg.loggerConfig = nil
cfg.loggerCore = cr cfg.loggerCore = nil
cfg.loggerWriteSyncer = syncer cfg.loggerWriteSyncer = nil
grpcLogOnce.Do(func() {
if cr != nil && syncer != nil {
grpclog.SetLoggerV2(logutil.NewGRPCLoggerV2FromZapCore(cr, syncer))
} else {
grpc_zap.ReplaceGrpcLoggerV2(cfg.logger.Named("grpc"))
}
})
return 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)
}
}

View File

@ -57,6 +57,8 @@ func startEtcdOrProxyV2(args []string) {
err := cfg.parse(args[1:]) err := cfg.parse(args[1:])
lg := cfg.ec.GetLogger() lg := cfg.ec.GetLogger()
cfg.ec.SetupGlobalLoggers()
if lg == nil { if lg == nil {
var zapError error var zapError error
// use this logger // use this logger

View File

@ -8,10 +8,8 @@ import (
"testing" "testing"
"go.etcd.io/etcd/client/pkg/v3/testutil" "go.etcd.io/etcd/client/pkg/v3/testutil"
"go.etcd.io/etcd/server/v3/embed"
) )
func TestMain(m *testing.M) { func TestMain(m *testing.M) {
embed.SetupGrpcLoggingForTest(true)
testutil.MustTestMainWithLeakDetection(m) testutil.MustTestMainWithLeakDetection(m)
} }

View File

@ -230,13 +230,13 @@ func restoreCluster(t *testing.T, clusterN int, dbPath string) (
ics := "" ics := ""
for i := 0; i < clusterN; i++ { 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:] ics = ics[1:]
cfgs := make([]*embed.Config, clusterN) cfgs := make([]*embed.Config, clusterN)
for i := 0; i < clusterN; i++ { 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.InitialClusterToken = testClusterTkn
cfg.ClusterState = "existing" cfg.ClusterState = "existing"
cfg.LCUrls, cfg.ACUrls = []url.URL{cURLs[i]}, []url.URL{cURLs[i]} cfg.LCUrls, cfg.ACUrls = []url.URL{cURLs[i]}, []url.URL{cURLs[i]}

View File

@ -20,9 +20,10 @@ import (
"testing" "testing"
grpc_logsettable "github.com/grpc-ecosystem/go-grpc-middleware/logging/settable" 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/client/pkg/v3/testutil"
"go.etcd.io/etcd/server/v3/embed" "go.etcd.io/etcd/server/v3/embed"
"go.uber.org/zap/zapcore"
"go.uber.org/zap/zapgrpc"
"go.uber.org/zap/zaptest" "go.uber.org/zap/zaptest"
) )
@ -35,7 +36,7 @@ func init() {
func BeforeTest(t testutil.TB) { func BeforeTest(t testutil.TB) {
testutil.BeforeTest(t) 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() previousWD, err := os.Getwd()
if err != nil { if err != nil {
@ -60,7 +61,8 @@ func MustAbsPath(path string) string {
func NewEmbedConfig(t testing.TB, name string) *embed.Config { func NewEmbedConfig(t testing.TB, name string) *embed.Config {
cfg := embed.NewConfig() cfg := embed.NewConfig()
cfg.Name = name 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() cfg.Dir = t.TempDir()
return cfg return cfg
} }