testing: minimization takes longer than expected for very large []byte/string

[katiehockman]

To reproduce, fuzz the following target with go test -fuzz Fuzz

func FuzzFoo(f *testing.F) {
	f.Fuzz(func(t *testing.T, b []byte) {
		if len(b) > 10000 {
			panic("bad")
		}
	})
}

The following output will occur:

fuzz: elapsed: 0s, gathering baseline coverage: 0/1 completed
fuzz: elapsed: 0s, gathering baseline coverage: 1/1 completed, now fuzzing with 8 workers
fuzz: minimizing 34995-byte crash input...
fuzz: elapsed: 3s, execs: 13821 (4604/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 6s, execs: 13821 (2303/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 9s, execs: 13821 (1535/sec), new interesting: 0 (total: 1)

Notice that it found a crash and indicated that it would minimize it, but then just proceeded with fuzzing anyway (Correction: It didn't keep fuzzing, it just kept updating the log. It looks like the worker hung). If you press Ctrl^C, it exits and writes the crasher:

fuzz: elapsed: 0s, gathering baseline coverage: 0/1 completed
fuzz: elapsed: 0s, gathering baseline coverage: 1/1 completed, now fuzzing with 8 workers
fuzz: minimizing 34995-byte crash input...
fuzz: elapsed: 3s, execs: 13821 (4604/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 6s, execs: 13821 (2303/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 9s, execs: 13821 (1535/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 12s, execs: 13821 (1152/sec), new interesting: 0 (total: 1)
^Cfuzz: elapsed: 14s, execs: 13821 (994/sec), new interesting: 0 (total: 1)
--- FAIL: FuzzAdd (13.90s)
        --- FAIL: FuzzAdd (0.00s)
            testing.go:1299: panic: bad
                goroutine 1506 [running]:
                runtime/debug.Stack()
                        /Users/katiehockman/godev/src/runtime/debug/stack.go:24 +0x90
                testing.tRunner.func1()
                        /Users/katiehockman/godev/src/testing/testing.go:1299 +0x5a5
                ...
                
    
    Crash written to testdata/fuzz/FuzzAdd/618b91bbfb35dd0736e9c6c90ed38973a2e1f5ebb7edf50714c31ae21b18d419
    To re-run:
    go test foo -run=FuzzAdd/618b91bbfb35dd0736e9c6c90ed38973a2e1f5ebb7edf50714c31ae21b18d419
FAIL
exit status 1
FAIL    foo     18.072s

Turning off minimization fixes this (e.g. go test -fuzz Fuzz -fuzzminimizetime=0x)

This also only seems to happen once the fuzzing engine has already run baseline coverage or found a new interesting value. If the target is changed to panic for every input, this bug won't occur and it'll crash as expected. e.g.

func FuzzAdd(f *testing.F) {
	f.Fuzz(func(t *testing.T, b []byte) {
		panic("bad")
	})
}

This also shows a hole in our testing. Most of our tests use -fuzztime in order to ensure they don't run for too long. However, using -fuzztime ends fuzzing after a certain number of iterations. That means we aren't testing that the fuzzing process will complete successfully if a crash occurs without help from -fuzztime.

/cc @golang/fuzzing

[katiehockman]

I figured out what's happening. For the example I provided, the crash only occurs if the []byte is at least 10,000 bytes. The original crash is 34,995 bytes long, which takes a long time to minimize. The first two minimization efforts (cutting the tail and removing every byte) run pretty quickly. However, removing every subset of bytes takes a very long time if the input is long.

If I am patient and just let it run for a while, then it will eventually hit that 1 minute minimization timeout and stop gracefully. The part that I found confusing is that it continues to print these "fuzz: elapsed:" messages after minimization has begun, which is a bit jarring and makes it look like the process is hanging. We should probably either 1) stop printing these log messages when we're minimizing or 2) update them to indicate the minimization progress. For (2) that could mean something like "fuzz: elapsed: 12s, minimizing"

[rsc]

(2) is much better, so the user knows it's not hung. If you were confused, they will be confused.

We should also probably do something about the removing subsets of bytes taking forever, but let's handle 'taking longer than user expected' gracefully first.

[katiehockman]

Yep agreed. I have a patch ready, and will send that shortly.

[gopherbot]

Change https://golang.org/cl/354371 mentions this issue: internal/fuzz: log that minimization is occurring

[katiehockman]

Moving this to the backlog for now, since at least (2) is done.