failed fuzz tests not reproducible when re-run

[Jochen Voss]

Dear all,

Recently I find quite often that after "go test -fuzz" reported an error, the command shown to re-run the test does not reproduce the failure.  For example, just now I got the following:

voss@dumpling [..nt/tounicode2] go test -fuzz FuzzToUnicode
fuzz: elapsed: 0s, gathering baseline coverage: 0/2 completed
fuzz: elapsed: 0s, gathering baseline coverage: 2/2 completed, now fuzzing with 10 workers
fuzz: elapsed: 3s, execs: 280461 (93481/sec), new interesting: 24 (total: 26)
fuzz: elapsed: 5s, execs: 410320 (72348/sec), new interesting: 60 (total: 62)
--- FAIL: FuzzToUnicode (4.80s)
    --- FAIL: FuzzToUnicode (0.00s)
        tounicode_test.go:129: template: tounicode:26:2: executing "tounicode" at <Single $cs .>: error calling Single: runtime error: integer divide by zero

    Failing input written to testdata/fuzz/FuzzToUnicode/2566873a28045c1b
    To re-run:
    go test -run=FuzzToUnicode/2566873a28045c1b
FAIL
exit status 1
FAIL seehuhn.de/go/pdf/font/tounicode2 4.957s
voss@dumpling [..nt/tounicode2] go test -run=FuzzToUnicode/2566873a28045c1b
PASS
ok   seehuhn.de/go/pdf/font/tounicode2 0.122s

The fuzzer reported a failure, and when I re-run the test I get a "PASS".

How to debug such a problem?

I understand that my fuzz function may somehow be non-deterministic, but so far I have not found any cause of non-determinism and re-running the test 10 times gives me 10 passes.  Also, for a bug the fuzzer reported earlier, I found it very hard to believe that the given input could make the fuzz function reach the site of the error message.  Could it be that the fuzzer sometimes looses track of which input belongs to which fuzzing run, and then reports the wrong input?

If somebody wants to play with this, here is how to reproduce (up to randomness) the fuzzing run shown above:

 git clone https://github.com/seehuhn/go-pdf.git
 cd go-pdf/
 git reset --hard 26c235ad
 cd font/tounicode2/
 go test -fuzz FuzzToUnicode

Any suggestions on how to debug such errors would be most welcome.

Many thanks,

Jochen

[William Rehwinkel]

Sorry, should have written this in the first email. I think another thing I would do to debug is fmt.Printf as many relevant variables as you can think of to see if any of them don't look right, but only make this happen when you have a failed test (where you would t.Fail()).

-William

[William Rehwinkel]

Dear Jochen,

If you open font/tounicode2/testdata/fuzz/FuzzToUnicode/2566873a28045c1b (or whatever appears after "Failing input written to")The file should contain the exact values passed to the test. It will look a bit like this

go test fuzz v1
string(".")
string("0")
 

This might give you a hint as to what is causing the problem. If this doesn't help, it sounds to me like there is a nasty race condition hidden in the code (as fuzz tests run concurrently) or some global variable is accessed which is occasionally changed during the test.

Thanks,

-William

On Wednesday, August 2, 2023 at 2:01:58 AM UTC-4 Jochen Voss wrote: