testing: fuzz corpus collection regression

[AlekSi]

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

go version devel go1.18-b2dc66c64d Thu Jan 27 16:07:55 2022 +0000 darwin/arm64

What did you do?

Run fuzzing before and after commit b2dc66c.

What did you expect to see?

More or less the same results.

What did you see instead?

Before that commit

$ go clean -cache -testcache -fuzzcache

$ go test -fuzz=FuzzArray -fuzztime=10s
fuzz: elapsed: 0s, gathering baseline coverage: 0/3 completed
fuzz: elapsed: 0s, gathering baseline coverage: 3/3 completed, now fuzzing with 10 workers
fuzz: elapsed: 3s, execs: 115569 (38294/sec), new interesting: 16 (total: 16)
fuzz: elapsed: 6s, execs: 115569 (0/sec), new interesting: 16 (total: 16)
fuzz: elapsed: 9s, execs: 115569 (0/sec), new interesting: 16 (total: 16)
fuzz: elapsed: 12s, execs: 122775 (2403/sec), new interesting: 18 (total: 18)
fuzz: elapsed: 12s, execs: 122775 (0/sec), new interesting: 18 (total: 18)
PASS
ok  	github.com/FerretDB/FerretDB/internal/bson	12.374s

go test -fuzz=FuzzArray -fuzztime=10s
fuzz: elapsed: 0s, gathering baseline coverage: 0/21 completed
fuzz: elapsed: 0s, gathering baseline coverage: 21/21 completed, now fuzzing with 10 workers
fuzz: elapsed: 3s, execs: 42415 (14138/sec), new interesting: 10 (total: 28)
fuzz: elapsed: 6s, execs: 42471 (19/sec), new interesting: 10 (total: 28)
fuzz: elapsed: 9s, execs: 42471 (0/sec), new interesting: 10 (total: 28)
fuzz: elapsed: 12s, execs: 42471 (0/sec), new interesting: 10 (total: 28)
fuzz: elapsed: 12s, execs: 42471 (0/sec), new interesting: 10 (total: 28)
PASS
ok  	github.com/FerretDB/FerretDB/internal/bson	12.294s

The first run has a baseline coverage of 3 (provided by f.Add). The second run starts with a coverage of 21: 3 + 18 from the previous run.

After that commit

$ go clean -cache -testcache -fuzzcache

$ go test -fuzz=FuzzArray -fuzztime=10s
fuzz: elapsed: 0s, gathering baseline coverage: 0/3 completed
fuzz: elapsed: 0s, gathering baseline coverage: 3/3 completed, now fuzzing with 10 workers
fuzz: elapsed: 3s, execs: 123346 (41046/sec), new interesting: 11 (total: 11)
fuzz: elapsed: 6s, execs: 183855 (20197/sec), new interesting: 15 (total: 15)
fuzz: elapsed: 9s, execs: 189491 (1876/sec), new interesting: 16 (total: 16)
fuzz: elapsed: 12s, execs: 189491 (0/sec), new interesting: 16 (total: 16)
fuzz: elapsed: 12s, execs: 189491 (0/sec), new interesting: 16 (total: 16)
PASS
ok  	github.com/FerretDB/FerretDB/internal/bson	12.561s

$ go test -fuzz=FuzzArray -fuzztime=10s
fuzz: elapsed: 0s, gathering baseline coverage: 0/4 completed
fuzz: elapsed: 0s, gathering baseline coverage: 4/4 completed, now fuzzing with 10 workers
fuzz: elapsed: 3s, execs: 49002 (16328/sec), new interesting: 6 (total: 7)
fuzz: elapsed: 6s, execs: 61815 (4271/sec), new interesting: 10 (total: 11)
fuzz: elapsed: 9s, execs: 61815 (0/sec), new interesting: 10 (total: 11)
fuzz: elapsed: 12s, execs: 61815 (0/sec), new interesting: 10 (total: 11)
fuzz: elapsed: 12s, execs: 61815 (0/sec), new interesting: 10 (total: 11)
PASS
ok  	github.com/FerretDB/FerretDB/internal/bson	12.443s

$ ls /Users/aleksi/Library/Caches/go-build/fuzz/github.com/FerretDB/FerretDB/internal/bson/FuzzArray | wc
      23      23    1495

$ go test -fuzz=FuzzArray -fuzztime=10s
fuzz: elapsed: 0s, gathering baseline coverage: 0/4 completed
fuzz: elapsed: 0s, gathering baseline coverage: 4/4 completed, now fuzzing with 10 workers
fuzz: elapsed: 3s, execs: 92355 (30774/sec), new interesting: 15 (total: 16)
fuzz: elapsed: 6s, execs: 92355 (0/sec), new interesting: 15 (total: 16)
fuzz: elapsed: 9s, execs: 102979 (3550/sec), new interesting: 17 (total: 18)
fuzz: elapsed: 12s, execs: 102979 (0/sec), new interesting: 17 (total: 18)
fuzz: elapsed: 12s, execs: 102979 (0/sec), new interesting: 17 (total: 18)
PASS
ok  	github.com/FerretDB/FerretDB/internal/bson	12.445s

$ ls /Users/aleksi/Library/Caches/go-build/fuzz/github.com/FerretDB/FerretDB/internal/bson/FuzzArray | wc
      32      32    2080

Notice how the second and the third runs start with 4.

I also noticed that my generated corpus, which was already quite big and did not grow much before that commit, started growing much faster after it. So it seems to be a corpus loading problem, not just a logging problem.

[AlekSi]

@gopherbot fuzz

[AlekSi]

/cc @katiehockman @rolandshoemaker

[gopherbot]

Change https://golang.org/cl/381960 mentions this issue: internal/fuzz: properly handle duplicates during cache loading

[AlekSi]

@katiehockman @rolandshoemaker After updating Go, I noticed the following in my fuzzing output::

fuzz: elapsed: 0s, gathering baseline coverage: 0/23 completed
fuzz: elapsed: 0s, gathering baseline coverage: 23/23 completed, now fuzzing with 6 workers
fuzz: elapsed: 3s, execs: 5420 (1806/sec), new interesting: 2 (total: 21)

Does it mean that four entries (23-(21-2)) in my corpus were duplicates? And those four entries are duplicates because they are present in both generated corpus and code? That makes sense, but I think that would be a source of questions and should be mentioned in docs.

[katiehockman]

This is currently documented at https://go.dev/doc/fuzz under "Command Line Output":

new interesting: the total number of “interesting” inputs that have been added to the generated corpus during this fuzzing execution (with the total size of the generated corpus)

I can see how that output might be a bit confusing. Maybe the total should be the size of the entire corpus, not just the generated corpus. @rolandshoemaker what do you think?

[rolandshoemaker]

Yeah making the total the combined size makes sense to me (without looking at the docs that was what I initially assumed that total was.)