Navigation Menu

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
shuLhan opened this issue Oct 3, 2022 · 6 comments
Closed

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

shuLhan opened this issue Oct 3, 2022 · 6 comments
Assignees
@thanm
Labels
FrozenDueToAge release-blocker
Milestone
Go1.20

Comments

@shuLhan
Copy link
Contributor

shuLhan commented Oct 3, 2022

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).
@shuLhan 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 bcmills added this to the Go1.20 milestone Oct 3, 2022
@bcmills
Copy link
Contributor

bcmills commented Oct 3, 2022

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
Copy link
Contributor

thanm commented Oct 3, 2022

Thanks, I'll take a look.

@thanm
Copy link
Contributor

thanm commented Oct 3, 2022

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
Copy link
Contributor

thanm commented Oct 3, 2022

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
Copy link

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

@gopherbot
Copy link

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

gopherbot pushed a commit that referenced this issue Oct 4, 2022
@thanm
cmd/internal/sys: migrate support.go functions to new internal pkg
8bd803f 
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>
@truthbk truthbk mentioned this issue Jan 20, 2023
Merged
@golang golang locked and limited conversation to collaborators Oct 4, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@thanm thanm

Labels
FrozenDueToAge release-blocker
Projects
None yet
Milestone
Go1.20
Development

No branches or pull requests
4 participants
@shuLhan @bcmills @gopherbot @thanm