cmd/go, testing: race detector finding a data race doesn't fail a test

[stevekuznetsov]

Environment details:

$ go version
go version go1.6.2 linux/amd64

$ go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/skuznets/Documents/go"
GORACE=""
GOROOT="/home/skuznets/.gvm/gos/go1.6.2"
GOTOOLDIR="/home/skuznets/.gvm/gos/go1.6.2/pkg/tool/linux_amd64"
GO15VENDOREXPERIMENT="1"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0"
CXX="g++"
CGO_ENABLED="1"

What did you do?

Run a unit test with a data race using the following invocation:

go test  -v -race -cover -covermode atomic -timeout 120s github.com/openshift/origin/pkg/service/controller/servingcert

What did you expect to see?

When the race detector is enabled and a data race is found, the unit test will fail.

What did you see instead?

The test passes, but the package fails:

=== RUN   TestSecretCreationErrorControllerFlow
I0606 13:37:58.051502   25372 controller.go:132] Shutting down service signing cert controller
==================
WARNING: DATA RACE
Write by goroutine 54:
  runtime.mapassign1()
      /home/skuznets/.gvm/gos/go1.6.2/src/runtime/hashmap.go:429 +0x0
  github.com/openshift/origin/pkg/service/controller/servingcert.(*ServiceServingCertController).syncService()
      github.com/openshift/origin/pkg/service/controller/servingcert/_test/_obj_test/controller.go:288 +0x21af
  github.com/openshift/origin/pkg/service/controller/servingcert.TestAlreadyExistingSecretForDifferentUIDControllerFlow.func2()
      /home/skuznets/Documents/go/src/github.com/openshift/origin/pkg/service/controller/servingcert/controller_test.go:234 +0xc2
  github.com/openshift/origin/pkg/service/controller/servingcert.(*ServiceServingCertController).worker_inner()
      github.com/openshift/origin/pkg/service/controller/servingcert/_test/_obj_test/controller.go:173 +0x20e
  github.com/openshift/origin/pkg/service/controller/servingcert.(*ServiceServingCertController).worker()
      github.com/openshift/origin/pkg/service/controller/servingcert/_test/_obj_test/controller.go:155 +0x6a
  github.com/openshift/origin/pkg/service/controller/servingcert.(*ServiceServingCertController).(github.com/openshift/origin/pkg/service/controller/servingcert.worker)-fm()
      github.com/openshift/origin/pkg/service/controller/servingcert/_test/_obj_test/controller.go:127 +0x2d
  k8s.io/kubernetes/pkg/util/wait.JitterUntil.func1()
      /home/skuznets/Documents/go/src/github.com/openshift/origin/Godeps/_workspace/src/k8s.io/kubernetes/pkg/util/wait/wait.go:66 +0x58
  k8s.io/kubernetes/pkg/util/wait.JitterUntil()
      /home/skuznets/Documents/go/src/github.com/openshift/origin/Godeps/_workspace/src/k8s.io/kubernetes/pkg/util/wait/wait.go:67 +0x7d
  k8s.io/kubernetes/pkg/util/wait.Until()
      /home/skuznets/Documents/go/src/github.com/openshift/origin/Godeps/_workspace/src/k8s.io/kubernetes/pkg/util/wait/wait.go:47 +0x4b

Previous read by goroutine 50:
  reflect.maplen()
      /home/skuznets/.gvm/gos/go1.6.2/src/runtime/hashmap.go:1029 +0x0
  reflect.Value.Len()
      /home/skuznets/.gvm/gos/go1.6.2/src/reflect/value.go:1007 +0x150
  reflect.deepValueEqual()
      /home/skuznets/.gvm/gos/go1.6.2/src/reflect/deepequal.go:106 +0xa14
  reflect.DeepEqual()
      /home/skuznets/.gvm/gos/go1.6.2/src/reflect/deepequal.go:185 +0x263
  github.com/openshift/origin/pkg/service/controller/servingcert.TestAlreadyExistingSecretForDifferentUIDControllerFlow()
      /home/skuznets/Documents/go/src/github.com/openshift/origin/pkg/service/controller/servingcert/controller_test.go:269 +0x163b
  testing.tRunner()
      /home/skuznets/.gvm/gos/go1.6.2/src/testing/testing.go:473 +0xdc

Goroutine 54 (running) created at:
  github.com/openshift/origin/pkg/service/controller/servingcert.(*ServiceServingCertController).Run()
      github.com/openshift/origin/pkg/service/controller/servingcert/_test/_obj_test/controller.go:127 +0x180

Goroutine 50 (finished) created at:
  testing.RunTests()
      /home/skuznets/.gvm/gos/go1.6.2/src/testing/testing.go:582 +0xae2
  testing.(*M).Run()
      /home/skuznets/.gvm/gos/go1.6.2/src/testing/testing.go:515 +0x11d
  main.main()
      github.com/openshift/origin/pkg/service/controller/servingcert/_test/_testmain.go:108 +0x385
==================
--- PASS: TestSecretCreationErrorControllerFlow (13.63s)
coverage: 81.2% of statements
Found 1 data race(s)
FAIL    github.com/openshift/origin/pkg/service/controller/servingcert  37.923s

[rsc]

It's true: we don't know which test case has the race. We just know that the overall test binary failed. In general test cases can run in parallel or have their background goroutines keep running after the test case is ostensibly over. So assigning races to specific test cases is harder than it sounds. Even so, if the race detector exposed the count of problems found so far, we could at least check to see if it increased during a particular test case.

@dvyukov, is it easy for Go to fetch the number of reported problems out of the race detector library on demand? Thanks.

[gopherbot]

CL https://golang.org/cl/32160 mentions this issue.

[dvyukov]

The updated race runtime exposes number of found races. It can be obtained with:

//go:nosplit
func RaceReportCount() int {
    var n uint64
    racecall(&__tsan_report_count, uintptr(unsafe.Pointer(&n)), 0, 0, 0)
    return int(n)
}

[gopherbot]

CL https://golang.org/cl/32615 mentions this issue.