Mirroristas/etcd
2
0
Fork 0
mirror of https://github.com/etcd-io/etcd.git synced 2024-09-27 06:25:44 +00:00
Code Issues Packages Projects Releases Wiki Activity

Fix flaky tests reported due to data race on grpc logging registration.

Browse Source 
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
```
This commit is contained in:
Piotr Tabor 2021-01-10 12:46:38 +01:00
parent c632042bb9
commit 8ccd4e1146
2 changed files with 23 additions and 13 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

34
server/embed/config_logging.go
View File

@ -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
}
}

2
tests/integration/main_test.go
View File

@ -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)
}