grpc / grpc-go

The Go language implementation of gRPC. HTTP/2 based RPC
https://grpc.io
Apache License 2.0
20.94k stars 4.35k forks source link

data race when enabling tracing #1084

Closed vrecan closed 6 years ago

vrecan commented 7 years ago

I get a data race when I set EnableTracing in my unit tests. I can't fix it easily because the goroutine reading the value exists in GRPC itself. This seems like something that should be a function that is mutex protected. For now I am going to work around it by hard coding it to false but I would really like to be able to use this without a potential race.

WARNING: DATA RACE
Write at 0x000001235305 by goroutine 15:
  github.schq.secious.com/UltraViolet/Winston/server.buildWinston()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/server/server.go:95 +0xa3
  github.schq.secious.com/UltraViolet/Winston/server.NewWinstonTest()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/server/server.go:89 +0x1b6
  github.schq.secious.com/UltraViolet/Winston/maintenance.Server()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/maintenance/maintenance_test.go:130 +0x47e
  github.schq.secious.com/UltraViolet/Winston/maintenance.TestIntegrationMaintenance.func2()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/maintenance/maintenance_test.go:114 +0x2d8
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey.parseAction.func1()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey/discovery.go:80 +0x3d
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey.(*context).conveyInner()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey/context.go:261 +0x1bd
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey.rootConvey.func1()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey/context.go:110 +0x194
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls._m()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls/stack_tags.go:39 +0x42
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls.markS()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls/stack_tags.go:16 +0x42
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls.addStackTag()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls/stack_tags.go:13 +0x47
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls.(*ContextManager).SetValues()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/jtolds/gls/context.go:92 +0x549
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey.rootConvey()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey/context.go:113 +0x4c7
  github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey.Convey()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/github.com/smartystreets/goconvey/convey/doc.go:75 +0x94
  github.schq.secious.com/UltraViolet/Winston/maintenance.TestIntegrationMaintenance()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/maintenance/maintenance_test.go:124 +0x35d
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:610 +0xc9

Previous read at 0x000001235305 by goroutine 19:
  github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc.(*ClientConn).resetAddrConn()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc/clientconn.go:505 +0x384
  github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc.(*addrConn).transportMonitor()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc/clientconn.go:849 +0x963
  github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc.(*ClientConn).resetAddrConn.func1()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc/clientconn.go:575 +0x26d

Goroutine 15 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:646 +0x52f
  testing.RunTests.func1()
      /usr/local/go/src/testing/testing.go:793 +0xb9
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:610 +0xc9
  testing.RunTests()
      /usr/local/go/src/testing/testing.go:799 +0x4ea
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:743 +0x12f
  main.main()
      github.schq.secious.com/UltraViolet/Winston/maintenance/_test/_testmain.go:56 +0x1b8

Goroutine 19 (finished) created at:
  github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc.(*ClientConn).resetAddrConn()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc/clientconn.go:576 +0x646
  github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc.DialContext.func2()
      /home/vrecan/go/src/github.schq.secious.com/UltraViolet/Winston/vendor/google.golang.org/grpc/clientconn.go:366 +0x2c2
vrecan commented 7 years ago

Is this a known issue, seems odd that no one cares about a data race?

menghanl commented 7 years ago

Which version are you using? What is google.golang.org/grpc/clientconn.go:505 showing in your vendered gRPC?

In the current master branch, https://github.com/grpc/grpc-go/blob/master/clientconn.go#L505 is a }.

23doors commented 7 years ago

Encountered same issue with 1.3.0 when using a logger that discards output. When I disabled tracing, it worked just fine.

WARNING: DATA RACE
Write at 0x000004b6c4d0 by goroutine 87:
  github.com/user/repo/pkg/lb.TestWorker()
      /Users/V/Go/src/github.com/user/repo/pkg/lb/worker_test.go:36 +0x6b
  testing.tRunner()
      /usr/local/Cellar/go/1.8.1/libexec/src/testing/testing.go:657 +0x107

Previous read at 0x000004b6c4d0 by goroutine 83:
  github.com/user/repo/vendor/google.golang.org/grpc/grpclog.Printf()
      /Users/V/Go/src/github.com/user/repo/vendor/google.golang.org/grpc/grpclog/logger.go:87 +0x3e
  github.com/user/repo/vendor/google.golang.org/grpc.(*ClientConn).resetAddrConn.func1()
      /Users/V/Go/src/github.com/user/repo/vendor/google.golang.org/grpc/clientconn.go:613 +0x159

Goroutine 87 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.8.1/libexec/src/testing/testing.go:697 +0x543
  testing.runTests.func1()
      /usr/local/Cellar/go/1.8.1/libexec/src/testing/testing.go:882 +0xaa
  testing.tRunner()
      /usr/local/Cellar/go/1.8.1/libexec/src/testing/testing.go:657 +0x107
  testing.runTests()
      /usr/local/Cellar/go/1.8.1/libexec/src/testing/testing.go:888 +0x4e0
  testing.(*M).Run()
      /usr/local/Cellar/go/1.8.1/libexec/src/testing/testing.go:822 +0x1c3
  main.main()
      github.com/user/repo/pkg/lb/_test/_testmain.go:48 +0x20f

Goroutine 83 (finished) created at:
  github.com/user/repo/vendor/google.golang.org/grpc.(*ClientConn).resetAddrConn()
      /Users/V/Go/src/github.com/user/repo/vendor/google.golang.org/grpc/clientconn.go:621 +0xae3
  github.com/user/repo/vendor/google.golang.org/grpc.DialContext.func3()
      /Users/V/Go/src/github.com/user/repo/vendor/google.golang.org/grpc/clientconn.go:403 +0x20c
23doors commented 7 years ago

Ok nevermind. In my case, disabling tracing didn't to a thing. It seems like a separate issue caused by setting grpc logger when -race is tested (set by grpclog.SetLogger(log.New(ioutil.Discard, "", 0)))

UPDATED: confirmed it as unrelated and pretty much issue with my own code. Setting grpclog logger once per package in TestMain fixed it. Disregard previous comment.

MakMukhi commented 7 years ago

@23doors Thanks for the update. @vrecan To pursue this bug we'll need more information from your side. Please respond to Menghan's comment, when you can. However, if this is not an issue anymore feel free to close it.