From 8ccd4e11463ce969c1ff36185effe06eff151d85 Mon Sep 17 00:00:00 2001 From: Piotr Tabor Date: Sun, 10 Jan 2021 12:46:38 +0100 Subject: [PATCH] Fix flaky tests reported due to data race on grpc logging registration. Example: ``` ================== WARNING: DATA RACE Write at 0x000002178320 by goroutine 575: google.golang.org/grpc/grpclog.SetLoggerV2() /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.29.1/grpclog/loggerv2.go:70 +0x444 go.etcd.io/etcd/server/v3/embed.(*Config).setupLogging.func1.1() /home/ptab/corp/etcd/server/embed/config_logging.go:119 +0x345 sync.(*Once).doSlow() /usr/lib/google-golang/src/sync/once.go:66 +0x109 sync.(*Once).Do() /usr/lib/google-golang/src/sync/once.go:57 +0x68 go.etcd.io/etcd/server/v3/embed.(*Config).setupLogging.func1() /home/ptab/corp/etcd/server/embed/config_logging.go:109 +0x3b1 go.etcd.io/etcd/server/v3/embed.(*Config).setupLogging() /home/ptab/corp/etcd/server/embed/config_logging.go:174 +0x6af go.etcd.io/etcd/server/v3/embed.(*Config).Validate() /home/ptab/corp/etcd/server/embed/config.go:553 +0x55 go.etcd.io/etcd/server/v3/embed.StartEtcd() /home/ptab/corp/etcd/server/embed/etcd.go:93 +0x84 go.etcd.io/etcd/tests/v3/integration.TestKVWithEmptyValue() /home/ptab/corp/etcd/tests/integration/v3_kv_test.go:33 +0x18c testing.tRunner() /usr/lib/google-golang/src/testing/testing.go:1123 +0x202 Previous read at 0x000002178320 by goroutine 956: [failed to restore the stack] Goroutine 575 (running) created at: testing.(*T).Run() /usr/lib/google-golang/src/testing/testing.go:1168 +0x5bb testing.runTests.func1() /usr/lib/google-golang/src/testing/testing.go:1441 +0xa6 testing.tRunner() /usr/lib/google-golang/src/testing/testing.go:1123 +0x202 testing.runTests() /usr/lib/google-golang/src/testing/testing.go:1439 +0x612 testing.(*M).Run() /usr/lib/google-golang/src/testing/testing.go:1347 +0x3c4 go.etcd.io/etcd/pkg/v3/testutil.MustTestMainWithLeakDetection() /home/ptab/corp/etcd/pkg/testutil/leak.go:150 +0x38 go.etcd.io/etcd/tests/v3/integration.TestMain() /home/ptab/corp/etcd/tests/integration/main_test.go:14 +0x272 main.main() _testmain.go:349 +0x269 Goroutine 956 (finished) created at: google.golang.org/grpc/internal/transport.newHTTP2Server() /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.29.1/internal/transport/http2_server.go:288 +0x18a4 google.golang.org/grpc/internal/transport.NewServerTransport() /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.29.1/internal/transport/transport.go:534 +0x2f5 google.golang.org/grpc.(*Server).newHTTP2Transport() /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.29.1/server.go:726 +0x2ca google.golang.org/grpc.(*Server).handleRawConn() /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.29.1/server.go:693 +0x60f google.golang.org/grpc.(*Server).Serve.func3() /home/ptab/private/golang/pkg/mod/google.golang.org/grpc@v1.29.1/server.go:663 +0x4c ================== ... {"level":"info","ts":"2021-01-09T22:21:04.550+0100","caller":"embed/etcd.go:330","msg":"closed etcd server","name":"default","data-dir":"/tmp/etcd-017337431","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} --- FAIL: TestKVWithEmptyValue (1.08s) v3_kv_test.go:62: my-namespace/foobar = data v3_kv_test.go:62: my-namespace/foobar1 = data v3_kv_test.go:62: namespace/foobar1 = data v3_kv_test.go:72: foobar = data v3_kv_test.go:72: foobar1 = data v3_kv_test.go:87: delete keys:2 testing.go:1038: race detected during execution of test ``` --- server/embed/config_logging.go | 34 +++++++++++++++++++++------------- tests/integration/main_test.go | 2 ++ 2 files changed, 23 insertions(+), 13 deletions(-) diff --git a/server/embed/config_logging.go b/server/embed/config_logging.go index 1b0909221..7ab81191e 100644 --- a/server/embed/config_logging.go +++ b/server/embed/config_logging.go @@ -40,6 +40,26 @@ func (cfg Config) GetLogger() *zap.Logger { // 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 { @@ -106,19 +126,7 @@ func (cfg *Config) setupLogging() error { c.loggerConfig = &copied c.loggerCore = nil c.loggerWriteSyncer = nil - grpcLogOnce.Do(func() { - // debug true, enable info, warning, error - // debug false, only discard info - if cfg.LogLevel == "debug" { - var gl grpclog.LoggerV2 - gl, err = logutil.NewGRPCLoggerV2(copied) - if err == nil { - grpclog.SetLoggerV2(gl) - } - } else { - grpclog.SetLoggerV2(grpclog.NewLoggerV2(ioutil.Discard, os.Stderr, os.Stderr)) - } - }) + setupGrpcLogging(cfg.LogLevel == "debug", copied) return nil } } diff --git a/tests/integration/main_test.go b/tests/integration/main_test.go index a4c8fd237..cb47a9d78 100644 --- a/tests/integration/main_test.go +++ b/tests/integration/main_test.go @@ -8,8 +8,10 @@ import ( "testing" "go.etcd.io/etcd/pkg/v3/testutil" + "go.etcd.io/etcd/server/v3/embed" ) func TestMain(m *testing.M) { + embed.SetupGrpcLoggingForTest(true) testutil.MustTestMainWithLeakDetection(m) }