testing: cover profile indicates zero coverage of function under test

[stevenjohnstone]

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

$ go version
go version devel go1.17-e5247f7886a Thu Sep 2 21:43:52 2021 +0000 linux/amd64

Does this issue reproduce with the latest release?

n/a

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/stevie/.cache/go-build"
GOENV="/home/stevie/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/stevie/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/stevie/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/stevie/sdk/gotip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/stevie/sdk/gotip/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="devel go1.17-e5247f7886a Thu Sep 2 21:43:52 2021 +0000"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/stevie/code/coverbug/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-build1073398343=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I have two files

package coverbug

import "testing"

func Fuzz(f *testing.F) {
	f.Fuzz(func(t *testing.T, a byte) {
		if magic(a) {
			panic(a)
		}
	})
}

package coverbug

func magic(a byte) bool {
	return a == 127
}

I run the beta fuzzer with coverage enabled

$ gotip test -fuzz=Fuzz -coverprofile=cover.out
found a crash, minimizing...
coverage: 100.0% of statements
coverage: 100.0% of statements
coverage: 0.0% of statements
coverage: 100.0% of statements
coverage: 100.0% of statements
coverage: 100.0% of statements
coverage: 100.0% of statements
coverage: 100.0% of statements
fuzzing, elapsed: 0.0s, execs: 184 (6166/sec), workers: 8, interesting: 0
--- FAIL: Fuzz (0.03s)
        panic: %!s(uint8=127)
        goroutine 48 [running]:
        runtime/debug.Stack()
        	/home/stevie/sdk/gotip/src/runtime/debug/stack.go:24 +0x90
        testing.tRunner.func1.2({0x58ce60, 0x6e2db8})
        	/home/stevie/sdk/gotip/src/testing/testing.go:1281 +0x267
        testing.tRunner.func1()
        	/home/stevie/sdk/gotip/src/testing/testing.go:1288 +0x218
        panic({0x58ce60, 0x6e2db8})
        	/home/stevie/sdk/gotip/src/runtime/panic.go:1038 +0x215
        coverbug.Fuzz.func1(0x0, 0x7f)
        	/home/stevie/code/coverbug/fuzz_test.go:8 +0x8b
        reflect.Value.call({0x58e940, 0x5c7bf0, 0x13}, {0x5ba226, 0x4}, {0xc00007aba0, 0x2, 0x2})
        	/home/stevie/sdk/gotip/src/reflect/value.go:543 +0x814
        reflect.Value.Call({0x58e940, 0x5c7bf0, 0xc000077e10}, {0xc00007aba0, 0x2, 0x2})
        	/home/stevie/sdk/gotip/src/reflect/value.go:339 +0xc5
        testing.(*F).Fuzz.func1.1(0xc00006a1e0)
        	/home/stevie/sdk/gotip/src/testing/fuzz.go:389 +0x1c6
        testing.tRunner(0xc0002361a0, 0xc000074b00)
        	/home/stevie/sdk/gotip/src/testing/testing.go:1335 +0x102
        created by testing.(*F).Fuzz.func1
        	/home/stevie/sdk/gotip/src/testing/fuzz.go:378 +0x505
        
        --- FAIL: Fuzz (0.00s)
    
    Crash written to testdata/corpus/Fuzz/4498dff1b840228ff50fd74740fe7690b5abeb3c9389d686b18a4bd3144abbbb
    To re-run:
    go test coverbug -run=Fuzz/4498dff1b840228ff50fd74740fe7690b5abeb3c9389d686b18a4bd3144abbbb
FAIL
coverage: 0.0% of statements
exit status 1
FAIL	coverbug	0.033s
$ cat cover.out 
mode: set
coverbug/magic.go:3.25,5.2 1 0

Note that the cover.out indicates zero coverage of the function magic, which can't be correct as the fuzzer just visited it before the panic.

If I run the test again, with coverage going to cover2.out, the previous crasher is read from ./testdata and used immediately in the corpus based test stage and I see

$ diff cover.out cover2.out 
2c2
< coverbug/magic.go:3.25,5.2 1 0
---
> coverbug/magic.go:3.25,5.2 1 1

Summary: run the fuzzer once to find a crasher, you get no coverage. Start the fuzzer again, you get coverage for the run using the crasher.

What did you expect to see?

I expected to see correct coverage information.

What did you see instead?

I saw zero counts on all the provided coverage points.

[cherrymui]

cc @golang/fuzzing

[jayconrod]

Unfortunately there's not a straightforward fix for this. We're going to need to figure out a better UX for this.

When fuzzing is enabled, there's a coordinator process (spawned by go test) and a number of worker processes (spawned by the coordinator), all running the instrumented test binary. We don't yet do anything to the flags passed to the coordinator, and the worker gets the same set of flags (plus a flag telling it to be a worker). That means the coordinator and all workers will collect coverage data and write it to the same file. The workers will race each other, but the coordinator doesn't exit until the workers are done, so it will write the file last. The coordinator only runs inputs from the testdata corpus and those added with F.Add, so that's all the coverage you'll see here.

There are a couple options here.

1. The coordinator could tell each worker to write coverage to a different file, then read those files, sum the counts together with its own coverage, and write a combined file. I don't think we have tooling for this, but the format isn't very complicated. However, there are plans underway to rebuild the coverage system and change the format, so this code might not survive very long.
2. The coordinator could report coverage for the "interesting" values we collected. The coordinator would not pass coverage flags to workers. When the coordinator stops, if coverage is enabled, it would re-run all the interesting inputs before coverage is written out. This would be rather simple to implement, but it would cause a delay between when the user stops fuzzing and when go test actually exits. The data would also be incomplete, especially in count and atomic modes.
3. The coordinator could just set a limit of one worker when coverage is enabled, then report coverage data from that worker. This is the simplest solution that provides an accurate result, but it throws out a lot of performance.

[jayconrod]

Marking as release-blocker. We could do (3) temporarily if that's all we have time for, then implement (1) later.

[katiehockman]

For now, we are going to disable -coverprofile when fuzzing (i.e. -fuzz is set). This may be added in future releases.

[toothrot]

Checking in on this issue as it's labeled a release blocker for Go 1.18. Is this still a release blocker?

[aclements]

@thanm , this may be of interest to the coverage improvements you're working on.

[thanm]

Thanks Austin. I'll add this to my list.

[thanm]

Q: would there also be potential issues when combining -fuzz with things like "-cpuprofile=..." ?

[jayconrod]

Q: would there also be potential issues when combining -fuzz with things like "-cpuprofile=..." ?

Probably yes... all the worker processes may end up writing to the same file.

We should look for flags like that and either have workers write to separate files and combine at the end, or disallow them altogether.

[heschi]

Ping again from the release meeting -- is this a release blocker?

[jayconrod]

Yes. At minimum we should disallow any instrumentation that writes to a file while fuzzing.

[toothrot]

cc @katiehockman Friendly ping that this is a release-blocking issue for Go 1.18.

[gopherbot]

Change https://golang.org/cl/360395 mentions this issue: cmd/go: disallow profile flags when using -fuzz

[turbolent]

Given that the coverprofile flag is currently disabled when fuzzing, how can we collect coverage information to determine how well our fuzzer is working?

[thanm]

Given that the coverprofile flag is currently disabled when fuzzing, how can we collect coverage information to determine how well our fuzzer is working?

Supporting this (combination of fuzzing and coverage profiling) will require some non-trivial implementation work. I'd suggest that we track this on a separate issue, as opposed to this one.

[fuzzah]

For now, we are going to disable -coverprofile when fuzzing (i.e. -fuzz is set). This may be added in future releases.

Please also consider disabling similar options combination for built binary... turns out it's possible to misleadingly build and run with coverprofile, but then it also gives 0% coverage:

go test . -fuzz=FuzzSomething -o fuzz -c -cover
./fuzz -test.fuzz=FuzzSomething -test.coverprofile=coverprofile.out