cmd/go: data race when running test with coverprofile #56006

shuLhan · 2022-10-03T04:24:49Z

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

$ go version
go version devel go1.20-1888875182 Sun Oct 2 15:42:47 2022 +0700 linux/amd64

Does this issue reproduce with the latest release?

No.

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN="/home/ms/go/bin"
GOCACHE="/home/ms/.cache/go-build"
GOENV="/home/ms/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/ms/go/pkg/mod"
GONOPROXY="github.com/tokenomy"
GONOSUMDB="github.com/tokenomy"
GOOS="linux"
GOPATH="/home/ms/go"
GOPRIVATE="github.com/tokenomy"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/ms/opt/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/ms/opt/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="devel go1.20-2807afbac6 Sun Oct 2 15:42:47 2022 +0700"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="0"
GOMOD="/dev/null"
GOWORK=""
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 -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3580077936=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I run go test with -race and -coverprofile at the same time on github.com/shuLhan/share and the test are FAIL with data race.

$ CGO_ENABLED=1 go test -failfast -race -count=1 -coverprofile=cover.out ./...
...
==================
WARNING: DATA RACE
Read at 0x000001e5f04c by main goroutine:
  internal/coverage/encodecounter.(*CoverageDataWriter).writeCounters.func2()
      /home/ms/opt/go/src/internal/coverage/encodecounter/encode.go:261 +0x11c
  runtime/coverage.(*emitState).VisitFuncs()
      /home/ms/opt/go/src/runtime/coverage/emit.go:539 +0x6bc
  internal/coverage/encodecounter.(*CoverageDataWriter).writeCounters()
      /home/ms/opt/go/src/internal/coverage/encodecounter/encode.go:268 +0x16f
  internal/coverage/encodecounter.(*CoverageDataWriter).AppendSegment()
      /home/ms/opt/go/src/internal/coverage/encodecounter/encode.go:175 +0x8ea
  internal/coverage/encodecounter.(*CoverageDataWriter).Write()
      /home/ms/opt/go/src/internal/coverage/encodecounter/encode.go:71 +0x97
  runtime/coverage.(*emitState).emitCounterDataFile()
      /home/ms/opt/go/src/runtime/coverage/emit.go:573 +0x91
  runtime/coverage.emitCounterDataToDirectory()
      /home/ms/opt/go/src/runtime/coverage/emit.go:322 +0x310
  runtime/coverage.processCoverTestDir()
      /home/ms/opt/go/src/runtime/coverage/testsupport.go:39 +0x1c4
  main.coverTearDown()
      _testmain.go:179 +0x159
  testing.coverReport2()
      /home/ms/opt/go/src/testing/newcover.go:37 +0xcb
  testing.coverReport()
      /home/ms/opt/go/src/testing/cover.go:83 +0xc74
  testing.(*M).writeProfiles()
      /home/ms/opt/go/src/testing/testing.go:2053 +0xc6f
  testing.(*M).after.func1()
      /home/ms/opt/go/src/testing/testing.go:1987 +0x30
  sync.(*Once).doSlow()
      /home/ms/opt/go/src/sync/once.go:74 +0x101
  sync.(*Once).Do()
      /home/ms/opt/go/src/sync/once.go:65 +0x46
  testing.(*M).after()
      /home/ms/opt/go/src/testing/testing.go:1986 +0x55
  testing.(*M).Run.func4()
      /home/ms/opt/go/src/testing/testing.go:1761 +0x39
  runtime.deferreturn()
      /home/ms/opt/go/src/runtime/panic.go:476 +0x32
  testing.(*M).Run()
      /home/ms/opt/go/src/testing/testing.go:1771 +0xbb3
  github.com/shuLhan/share/lib/dns.TestMain()
      /home/ms/go/src/github.com/shuLhan/share/lib/dns/dns_test.go:63 +0x5db
  main.main()
      _testmain.go:192 +0x33d

Previous write at 0x000001e5f04c by goroutine 9:
  sync/atomic.AddInt32()
      /home/ms/opt/go/src/runtime/race_amd64.s:281 +0xb
  sync/atomic.AddUint32()
      <autogenerated>:1 +0x1a
  github.com/shuLhan/share/lib/dns.(*Server).processRequest()
      /home/ms/go/src/github.com/shuLhan/share/lib/dns/server.go:593 +0xc67
  github.com/shuLhan/share/lib/dns.(*Server).ListenAndServe.func1()
      /home/ms/go/src/github.com/shuLhan/share/lib/dns/server.go:187 +0x39

Goroutine 9 (running) created at:
  github.com/shuLhan/share/lib/dns.(*Server).ListenAndServe()
      /home/ms/go/src/github.com/shuLhan/share/lib/dns/server.go:187 +0xe6
  github.com/shuLhan/share/lib/dns.TestMain.func1()
      /home/ms/go/src/github.com/shuLhan/share/lib/dns/dns_test.go:54 +0x44
==================
...

There are many lines like that with the same pattern.

In the above snippet, the lib/dns/dns_test.go:63 point this code [1],

os.Exit(m.Run())

inside the TestMain. So it does not make sense if the data race is in my code.

A quick bisect point to this commit [2].

I run the test using GOEXPERIMENT=coverageredesign flag using Go tip commit 53773a5

$ go version
go version devel go1.20-53773a5d08 Wed Sep 28 11:50:58 2022 +0000 linux/amd64

Without GOEXPERIMENT flag,

$ CGO_ENABLED=1 go test -race -coverprofile=cover.out ./lib/dns
ok      github.com/shuLhan/share/lib/dns        0.707s  coverage: 56.8% of statements

With GOEXPERIMENT=coverageredesign flag,

$ GOEXPERIMENT=coverageredesign CGO_ENABLED=1 go test -race ./lib/dns
ok      github.com/shuLhan/share/lib/dns        0.683s

$ GOEXPERIMENT=coverageredesign CGO_ENABLED=1 go test -race -coverprofile=cover.out ./lib/dns
dns.Server: listening for DNS over TLS at 127.0.0.1:18053
dns.Server: listening for DNS over TCP at 127.0.0.1:5300
dns.Server: listening for DNS over UDP at 127.0.0.1:5300
dns.Server: listening for DNS over HTTPS at 127.0.0.1:8443
dns: invalid IP address "localhost"
dns: invalid name server URI "://127.0.0.1"
dns: invalid IP address "localhost:53"
dns: invalid IP address "localhost:53"
PASS
==================
WARNING: DATA RACE
Read at 0x000001e5f04c by main goroutine:
  internal/coverage/encodecounter.(*CoverageDataWriter).writeCounters.func2()
      /home/ms/opt/go/src/internal/coverage/encodecounter/encode.go:261 +0x11c
  runtime/coverage.(*emitState).VisitFuncs()
      /home/ms/opt/go/src/runtime/coverage/emit.go:539 +0x6bc
  internal/coverage/encodecounter.(*CoverageDataWriter).writeCounters()
      /home/ms/opt/go/src/internal/coverage/encodecounter/encode.go:268 +0x16f
...

[1] https://github.com/shuLhan/share/blob/61720a183756bdf5a8af45e7d75116ce7ef188e0/lib/dns/dns_test.go#L63
[2] https://go.googlesource.com/go/+/53773a5d0892be4489b4d5e91bbc8ae61000ada7%5E%21/

What did you expect to see?

All test running succesfully.

What did you see instead?

Some test are FAIL-ed due to data race but point to code that are not relevant (in this case the race is inside TestMain function).

The text was updated successfully, but these errors were encountered:

bcmills · 2022-10-03T17:46:42Z

This appears to be caused by a goroutine leaked by a test racing with the coverage instrumentation writing out the counters associated with that goroutine.

The testing package does not prohibit goroutine leaks, so this is a bug in the coverage instrumentation. (Perhaps it can be resolved by changing encodecounter to use atomic reads?)

The leaked goroutine is started here:
https://github.com/shuLhan/share/blob/61720a183756bdf5a8af45e7d75116ce7ef188e0/lib/dns/server.go#L187

thanm · 2022-10-03T17:53:47Z

Thanks, I'll take a look.

thanm · 2022-10-03T18:01:06Z

This is an interesting bug, since coverage counters are (in theory) supposed to be specially marked as such, and should be "invisible" to the race detector. The fact that you're seeing this problem is an indication that something is going wrong with this process.... more investigation needed.

thanm · 2022-10-03T19:52:44Z

OK, the code added to the compiler intended to defeat the race detector instrumentation for coverage counters looks like it only applies to direct reads and writes, as opposed to those done via atomic read/write clls (where we don't have an option of turning things off). I'll rework the counter emit code to use atomics as well.

gopherbot · 2022-10-03T22:45:55Z

Change https://go.dev/cl/438256 mentions this issue: runtime/coverage: use atomic access for counter reads

gopherbot · 2022-10-04T13:20:05Z

Change https://go.dev/cl/438475 mentions this issue: cmd/internal/sys: migrate support.go functions to new internal pkg

Separate out the functions from cmd/internal/sys/support.go and migrate them to a new package internal/platform, so that functions such as "RaceDetectorSupported" can be called from tests in std as well as in cmd. This isn't a complete move of everything in cmd/internal/sys; there are still many functions left. The original version of this CL (patch set 1) called the new package "internal/sys", but for packages that needed both "internal/sys" and "cmd/internal/sys" the import of the former had to be done with a different name, which was confusing and also required a hack in cmd/dist. Updates #56006. Change-Id: I866d62e75adbf3a640a06e2c7386a6e9e2a18d91 Reviewed-on: https://go-review.googlesource.com/c/go/+/438475 Reviewed-by: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Cherry Mui <cherryyz@google.com> Run-TryBot: Than McIntosh <thanm@google.com>

shuLhan changed the title ~~cmd/go: data race when running test with coverage~~ cmd/go: data race when running test with coverprofile Oct 3, 2022

bcmills assigned thanm Oct 3, 2022

bcmills added this to the Go1.20 milestone Oct 3, 2022

bcmills added the release-blocker label Oct 3, 2022

gopherbot closed this as completed in cddf792 Oct 4, 2022

truthbk mentioned this issue Jan 20, 2023

[test] disable -coverprofile until 1.20 DataDog/datadog-agent-macos-build#130

Merged

golang locked and limited conversation to collaborators Oct 4, 2023

gopherbot added the FrozenDueToAge label Oct 4, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/go: data race when running test with coverprofile #56006

cmd/go: data race when running test with coverprofile #56006

shuLhan commented Oct 3, 2022

bcmills commented Oct 3, 2022

thanm commented Oct 3, 2022

thanm commented Oct 3, 2022

thanm commented Oct 3, 2022

gopherbot commented Oct 3, 2022

gopherbot commented Oct 4, 2022

cmd/go: data race when running test with coverprofile #56006

cmd/go: data race when running test with coverprofile #56006

Comments

shuLhan commented Oct 3, 2022

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

bcmills commented Oct 3, 2022

thanm commented Oct 3, 2022

thanm commented Oct 3, 2022

thanm commented Oct 3, 2022

gopherbot commented Oct 3, 2022

gopherbot commented Oct 4, 2022

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

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