testing,internal/fuzz: improve detection and reporting of deadlocks during fuzzing

[bcmills]

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

$ go version
go version devel go1.18-abbfec282 Thu Sep 23 15:10:56 2021 +0000 linux/amd64

Does this issue reproduce with the latest release?

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/usr/local/google/home/bcmills/.cache/go-build"
GOENV="/usr/local/google/home/bcmills/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/tmp/tmp.jThznCU2hQ/.gopath/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/tmp/tmp.jThznCU2hQ/.gopath"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/google/home/bcmills/sdk/gotip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/google/home/bcmills/sdk/gotip/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="devel go1.18-abbfec282 Thu Sep 23 15:10:56 2021 +0000"
GCCGO="/usr/local/google/home/bcmills/bin/gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="c++"
CGO_ENABLED="1"
GOMOD="/tmp/tmp.jThznCU2hQ/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-build1407505130=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Run the test below with go test -fuzz=. -fuzztime=30s:

package main

import "testing"

func FuzzDeadlock(f *testing.F) {
	f.Fuzz(func(t *testing.T, n int) {
		if n == 1000 {
			select {}
		}
	})
}

What did you expect to see?

Either an explicit error from the fuzzer indicating that the test deadlocked, or a hang until some timeout expired — either way, resulting in a nonzero exit code.

#48157 is also very relevant, but would not help in this case if the per-test timeout is set close to (or higher than) -fuzztime.

What did you see instead?

$ go test -fuzz=. -fuzztime=30s .
warning: starting with empty corpus
fuzz: elapsed: 0s, execs: 0 (0/sec), interesting: 0
fuzz: elapsed: 3s, execs: 105801 (35240/sec), interesting: 1
fuzz: elapsed: 6s, execs: 105801 (17624/sec), interesting: 1
fuzz: elapsed: 9s, execs: 105801 (11751/sec), interesting: 1
fuzz: elapsed: 12s, execs: 105801 (8814/sec), interesting: 1
fuzz: elapsed: 15s, execs: 105801 (7052/sec), interesting: 1
fuzz: elapsed: 18s, execs: 105801 (5877/sec), interesting: 1
fuzz: elapsed: 21s, execs: 105801 (5037/sec), interesting: 1
fuzz: elapsed: 24s, execs: 105801 (4408/sec), interesting: 1
fuzz: elapsed: 27s, execs: 105801 (3918/sec), interesting: 1
fuzz: elapsed: 30s, execs: 105801 (3526/sec), interesting: 1
fuzz: elapsed: 32s, execs: 105801 (3306/sec), interesting: 1
PASS
ok      example 32.017s

(Note that the execs count got stuck — and the reported throughput started dropping — as soon as the deadlock was found.)

[bcmills]

I tried hacking in my own deadlock-detection like this:

		timer := time.AfterFunc(10*time.Second, func() {
			panic("deadlocked!")
		})
		defer timer.Stop()

Unfortunately, that seems to have confused the minimizer, because it emitted a testdata file that doesn't reproduce the deadlock in my actual package even when run with a very high -count.

[katiehockman]

I think what we need to do here is set some kind of timer on the coordinator side to watch for a response from the worker. If we don't see one, we kill the worker, indicate the minimization is not allowed, write the failing input, and return a non-zero exit status.

[gopherbot]

Change https://golang.org/cl/363134 mentions this issue: internal/fuzz: set timeout for each exec of fuzz target