testing: fuzzing results include duplicate output

[mvdan]

$ go version
go version devel go1.18-7fcf9a1e58 Fri Oct 8 19:41:16 2021 +0000 linux/amd64
$ cat fuzz_test.go 
package main

import (
	"testing"
)

func FuzzFoo(f *testing.F) {
	f.Logf("parent f.Logf")
	f.Fuzz(func(t *testing.T, n uint8) {
		f.Logf("child f.Logf %d", n) // I'm allowed to use f.Logf here? f.Fatalf panics.
		t.Logf("child t.Logf %d", n)
		if n%3 == 0 {
			t.Fatal("boom")
		}
	})
}

If I then fuzz via go test -fuzz=. on an empty corpus, I get:

$ rm -rf testdata/fuzz && rm -rf $(go env GOCACHE)/fuzz
$ go test -fuzz=.
warning: starting with empty corpus
fuzz: elapsed: 0s, execs: 0 (0/sec), new interesting: 0 (total: 0)
fuzz: minimizing 26-byte crash input...
fuzz: elapsed: 0s, minimizing
--- FAIL: FuzzFoo (0.10s)
    fuzz_test.go:8: parent f.Logf
        fuzz_test.go:8: parent f.Logf
        fuzz_test.go:10: child f.Logf 78
        --- FAIL: FuzzFoo (0.00s)
            fuzz_test.go:11: child t.Logf 78
            fuzz_test.go:13: boom
        fuzz_test.go:10: child f.Logf 78
        --- FAIL: FuzzFoo (0.00s)
            fuzz_test.go:11: child t.Logf 78
            fuzz_test.go:13: boom
        fuzz_test.go:10: child f.Logf 78
        --- FAIL: FuzzFoo (0.00s)
            fuzz_test.go:11: child t.Logf 78
            fuzz_test.go:13: boom
    
    Crash written to testdata/fuzz/FuzzFoo/eca4c171b466a632930330d73dc661bd6d35f037e8dc7f2314c1adfc855b008b
    To re-run:
    go test test -run=FuzzFoo/eca4c171b466a632930330d73dc661bd6d35f037e8dc7f2314c1adfc855b008b
FAIL
exit status 1
FAIL	test	0.106s

I see multiple unexpected issues:

1. Note the two parent f.Logf lines. I suspect one of them is redundant. My actual fuzz func logged over a dozen times while calling f.Add, so the duplication really added a lot of noise.

2. I'm kinda confused why I see three separate --- FAIL: FuzzFoo blocks, all sharing the same input 78. Presumably the fuzzer should only test each input case once? If keeping track of all visited inputs or otherwise avoiding duplicates is too expensive, then at least we should be deduplicating the results being printed. To the end user, printing the same failure result more than once is unnecessary noise.

3. Note how child f.Logf is allowed and ends up being printed along with parent f.Logf. It is not allowed to call f.Fatalf from inside the fuzz function taking a *testing.T, so I think we should similarly disallow calling any testing.TB methods on the parent *testing.F, such as Logf. I actually used f.Logf instead of t.Logf by mistake, and was very confused why my log lines ended up in the wrong position in the resulting failure output.

These are three bugs into one, apologies :) I actually only intended to file number 3, but I ran into 1 and 2 while writing the reproducer. All three issues seem small and related enough to be OK within a single thread.

cc @katiehockman @jayconrod

[mvdan]

Also, what is the minimization actually doing with 26 bytes? My input is one byte :)

[katiehockman]

Thanks for filing this!

1. Note the two parent f.Logf lines...

I think this is a duplicate of #48709, or at least will be fixed as a side effect once a fix is merged. If it's not, then we should look at this one again.

2. I'm kinda confused why I see three separate --- FAIL: FuzzFoo blocks, all sharing the same input 78....

Same thing here. I think it's a dupe of #48709. If there is a crash, we re-run it at least 1 time to be sure it wasn't a flake, so that might be what you're seeing here as far as duplicate print statements.

3. Note how child f.Logf is allowed and ends up being printed along with parent f.Logf. It is not allowed to call f.Fatalf from inside the fuzz function taking a *testing.T, so I think we should similarly disallow calling any testing.TB methods on the parent *testing.F, such as Logf. I actually used f.Logf instead of t.Logf by mistake, and was very confused why my log lines ended up in the wrong position in the resulting failure output.

I agree. We panic for most other *testing.F functions. If you're in f.Fuzz, you should use t.Logf instead.

Also, what is the minimization actually doing with 26 bytes? My input is one byte :)

That's... a good question. Will look into this one. I have a suspicion of what might be going on here, but will double check. (It's possible we're printing the size of the marshaled corpus file, instead of the size of the unmarshaled value, which could explain where those extra 25 bytes are coming from)

[mvdan]

Thanks for the prompt reply! I thought some of these might be partial duplicates. I'm happy to give the reproducer another try after some fixes are merged.

[katiehockman]

I went ahead and filed #48988 and #48989 for the other two issues that you filed here. It's easier for me to track it that way.

We'll keep this one open, and have you double check that it's fixed after the fix from #48709 is merged.

[katiehockman]

Hey @mvdan I just merged https://golang.org/cl/355909 which hopefully fixed this duplicate output issue. Would you be able to double check and see if this issue still reproduces for you? If not, you can close this.

[mvdan]

I can confirm that all three bugs appear to be fixed! Thanks for your work :)

[katiehockman]

Woo! Great news 😄