Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

testing: fuzzing results include duplicate output #48884

Closed
mvdan opened this issue Oct 9, 2021 · 7 comments
Closed

testing: fuzzing results include duplicate output #48884

mvdan opened this issue Oct 9, 2021 · 7 comments
Labels
FrozenDueToAge fuzz Issues related to native fuzzing support WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone

Comments

@mvdan
Copy link
Member

mvdan commented Oct 9, 2021

$ 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 mvdan added the fuzz Issues related to native fuzzing support label Oct 9, 2021
@mvdan
Copy link
Member Author

mvdan commented Oct 9, 2021

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

@seankhliao seankhliao added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 9, 2021
@katiehockman katiehockman added this to the Go1.18 milestone Oct 12, 2021
@katiehockman
Copy link
Contributor

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.

  1. 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.

  1. 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
Copy link
Member Author

mvdan commented Oct 12, 2021

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
Copy link
Contributor

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 katiehockman added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. and removed release-blocker NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 14, 2021
@katiehockman
Copy link
Contributor

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.

@katiehockman katiehockman added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 19, 2021
@mvdan
Copy link
Member Author

mvdan commented Nov 2, 2021

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

@mvdan mvdan closed this as completed Nov 2, 2021
@katiehockman
Copy link
Contributor

Woo! Great news 😄

@golang golang locked and limited conversation to collaborators Nov 2, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge fuzz Issues related to native fuzzing support WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
Status: No status
Development

No branches or pull requests

4 participants