runtime/race: misses race in gRPC server because of timing

[pohly]

What version of Go are you using (go version)?

$ go version
go version go1.12.6 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/pohly/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/nvme/gopath"
GOPROXY=""
GORACE=""
GOROOT="/nvme/gopath/go"
GOTMPDIR=""
GOTOOLDIR="/nvme/gopath/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/work/grpc-locking/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build250390168=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I want to enable the Go race detector in the testing of a gRPC server. gRPC calls methods concurrently in different goroutines, so those methods have to protect access to shared data via locks. I got the race detector working (it reported an artificially introduced race) but some other race (found via code review) wasn't reported although the faulty code gets invoked by different goroutines (verified via debug output).

I reduced it to a simpler example that works with just a single go test command:
https://github.com/pohly/grpc-locking

To reproduce (more details in the repo's README.md):

• check out that repo
• go test -v -race -run=TestGRPC . -args -delay=10ms

The delay is important. It configures the duration of a sleep between starting two goroutines which call the faulty code through gRPC. This simulates the random timing that occurs when different clients call the server from remote.

It's also relevant that gRPC is involved. The race detector always works when calling the methods directly.

What did you expect to see?

I expect to get the race reported regardless of the delay.

What did you see instead?

The race is only reported when the delay is small, like 1ms.

[pohly]

My current hypothesis is that the delay causes gRPC on the server side to behave sufficiently different (perhaps doing additional IO?) that the race detector sees an ordering of the goroutines that isn't actually guaranteed in this case. This might be similar to #27756.

But I don't know enough about the race detector and/or gRPC implementation to determine whether that is the case. My hope is that someone can look at this and determine whether this is a bug and/or something that can be made to work (which would be great!).

[ianlancetaylor]

CC @dvyukov

[dvyukov]

I don't think we can make this to work. Parasitic synchronization is the problem for any happens-before-based race detectors. But this is the price for absence of false positives. The idea is if the test is run multiple times (e.g. continuous testing) then any race should pop up eventually.

[pohly]

Thanks for the confirmation that this is simply how race detector works. Please feel free to close this issue.

Regarding running the test multiple times: in this case the risk of it going wrong is so low, I doubt it will ever occur during normal functional testing. An API test that is specifically written to access the same object in multiple goroutines triggers it (I checked and added such a test), but that implies that the developer writing the code already knows about the need to do locking.

That's why I was hoping that the race detector would find it.

[dvyukov]

As some rehabilitation: there is a positive correlation between the probability that race detector finds a race and that it's actually harmful in real life. Which is good. For example, if there is something that gives a soft guarantee that the racing accesses happen no closer than a minute, then the race detector may not find it but it is probably not so harmful in real life.
Though, of course, it's also possible that the test runs under race detector are not representative of all real life behaviors. And then race detector will miss something that actually can happen in real life.