tip: data race when running test with coverage

[Shulhan]

Hi gophers,

The latest Go tip always fail with data race when running with -race
and -coverprofile options.

Here is an example of data race output,

----
$ 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())

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

A quick bisect point to this commit [2].

If someone can confirm this, I will submit an issue to GitHub.

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

--
{ "git":"git.sr.ht/~shulhan", "site":"kilabit.info" }

[Rob Pike]

When running coverage in a concurrent program, use the -mode=atomic flag to avoid data races in the counters. This unavoidably has a significant performance hit, but it should resolve this race.

-rob

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/20221002011006.4ffaaaec%40inspiro.localdomain.

[Shulhan]

On Sun, 2 Oct 2022 10:41:17 +1100
Rob Pike <r...@golang.org> wrote:

> When running coverage in a concurrent program, use the -mode=atomic
> flag to avoid data races in the counters. This unavoidably has a
> significant performance hit, but it should resolve this race.
>
> -rob
>

This flag print "no test files" when running go test,

$ GOEXPERIMENT=coverageredesign CGO_ENABLED=1 go test -mode=atomic -race -coverprofile=cover.out ./lib/dns
? github.com/shuLhan/share [no test files]

Not sure I am using the flag correctly or not since I cannot find it in
the current documentation [1].

[1] https://pkg.go.dev/cmd/go

Just want to be clear, I run the test using
GOEXPERIMENT=coverageredesign flag using Go tip commit 53773a5d08

$ 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

...
----

[Rob Pike]

Apologies, the cover tool calls it -mode but the go command calls it -covermode.

go test -covermode=atomic

-rob

[Rob Pike]

Also, it is documented:

% go help testflag | grep mode

-covermode set,count,atomic

    Set the mode for coverage analysis for the package[s]

When 'go test' runs in package list mode, 'go test' caches successful

% 

[Shulhan]

On Sun, 2 Oct 2022 19:22:21 +1100
Rob Pike <r...@golang.org> wrote:

> Apologies, the cover tool calls it -mode but the go command calls it
> -covermode.
>
> go test -covermode=atomic
>
> -rob
>
>

Got it, thanks, but it still fail with the data race.

----
(ins) 1 $ GOEXPERIMENT=coverageredesign CGO_ENABLED=1 go test -covermode=atomic -race -coverprofile=cover.out ./lib/dns

dns.Server: listening for DNS over UDP at 127.0.0.1:5300
dns.Server: listening for DNS over TCP at 127.0.0.1:5300

dns.Server: listening for DNS over TLS at 127.0.0.1:18053

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
...

Found 12 data race(s)
FAIL github.com/shuLhan/share/lib/dns 0.754s
FAIL
----

BTW, from documentation, the -race flag automatically set the
-covermode=atomic.

-covermode set,count,atomic
...
being tested. The default is "set" unless -race is enabled,
in which case it is "atomic".
...

So I think its redundant to set -race and -covermode=atomic at the same
time.

[Rob Pike]

This is a race in new code, then, so please file an issue at
https://go.dev/issue/new

-rob

[Shulhan]

On Sun, 2 Oct 2022 20:45:08 +1100
Rob Pike <r...@golang.org> wrote:

> This is a race in new code, then, so please file an issue at
> https://go.dev/issue/new
>
> -rob
>

Done, https://github.com/golang/go/issues/56006

Thank you for walking me through this.