From: Katie Hockman Date: Thu, 4 Mar 2021 19:53:18 +0000 (-0500) Subject: [dev.fuzz] testing: print logs and error messages when fuzzing X-Git-Tag: go1.18beta1~1282^2~80 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=9d4d5ee66dc53f6640dd8f5333df69db4df3b044;p=gostls13.git [dev.fuzz] testing: print logs and error messages when fuzzing Also improve the error messages for the use of testing.F functions inside the Fuzz function. Change-Id: I5fa48f8c7e0460a1da89a49a73e5af83c544e549 Reviewed-on: https://go-review.googlesource.com/c/go/+/298849 Trust: Katie Hockman Run-TryBot: Katie Hockman TryBot-Result: Go Bot Reviewed-by: Jay Conrod --- diff --git a/src/cmd/go/testdata/script/test_fuzz_mutate_crash.txt b/src/cmd/go/testdata/script/test_fuzz_mutate_crash.txt index bd9ce5c512..a143edda08 100644 --- a/src/cmd/go/testdata/script/test_fuzz_mutate_crash.txt +++ b/src/cmd/go/testdata/script/test_fuzz_mutate_crash.txt @@ -37,16 +37,19 @@ go run check_testdata.go FuzzWithNilPanic stdout 'testdata[/\\]corpus[/\\]FuzzWithFail[/\\]' go run check_testdata.go FuzzWithFail +! go test -run=FuzzWithLogFail -fuzz=FuzzWithLogFail -fuzztime=5s +stdout 'testdata[/\\]corpus[/\\]FuzzWithLogFail[/\\]' +stdout 'logged something' +go run check_testdata.go FuzzWithLogFail + ! go test -run=FuzzWithErrorf -fuzz=FuzzWithErrorf -fuzztime=5s stdout 'testdata[/\\]corpus[/\\]FuzzWithErrorf[/\\]' -# TODO: Uncomment this part of the test once it's fixed -# stdout 'errorf was called here' +stdout 'errorf was called here' go run check_testdata.go FuzzWithErrorf ! go test -run=FuzzWithFatalf -fuzz=FuzzWithFatalf -fuzztime=5s stdout 'testdata[/\\]corpus[/\\]FuzzWithFatalf[/\\]' -# TODO: Uncomment this part of the test once it's fixed -# stdout 'fatalf was called here' +stdout 'fatalf was called here' go run check_testdata.go FuzzWithFatalf ! go test -run=FuzzWithBadExit -fuzz=FuzzWithBadExit -fuzztime=5s @@ -93,6 +96,16 @@ func FuzzWithFail(f *testing.F) { }) } +func FuzzWithLogFail(f *testing.F) { + f.Add([]byte("aa")) + f.Fuzz(func(t *testing.T, b []byte) { + if string(b) != "aa" { + t.Log("logged something") + t.Fail() + } + }) +} + func FuzzWithErrorf(f *testing.F) { f.Add([]byte("aa")) f.Fuzz(func(t *testing.T, b []byte) { diff --git a/src/internal/fuzz/worker.go b/src/internal/fuzz/worker.go index 70d76d6fc6..3fe5aebbf4 100644 --- a/src/internal/fuzz/worker.go +++ b/src/internal/fuzz/worker.go @@ -137,7 +137,7 @@ func (w *worker) runFuzzing() error { mem := <-w.memMu value := mem.valueCopy() w.memMu <- mem - message := fmt.Sprintf("fuzzing process terminated unexpectedly: %v", w.waitErr) + message := fmt.Sprintf("fuzzing process terminated unexpectedly: %v\n", w.waitErr) crasher := crasherEntry{ CorpusEntry: CorpusEntry{Data: value}, errMsg: message, diff --git a/src/testing/fuzz.go b/src/testing/fuzz.go index c855379566..2a0754fdd7 100644 --- a/src/testing/fuzz.go +++ b/src/testing/fuzz.go @@ -73,7 +73,7 @@ type corpusEntry = struct { // first called order. func (f *F) Cleanup(fn func()) { if f.inFuzzFn { - panic("testing: f.Cleanup was called inside the f.Fuzz function") + panic("testing: f.Cleanup was called inside the f.Fuzz function, use t.Cleanup instead") } f.common.Helper() f.common.Cleanup(fn) @@ -82,7 +82,7 @@ func (f *F) Cleanup(fn func()) { // Error is equivalent to Log followed by Fail. func (f *F) Error(args ...interface{}) { if f.inFuzzFn { - panic("testing: f.Error was called inside the f.Fuzz function") + panic("testing: f.Error was called inside the f.Fuzz function, use t.Error instead") } f.common.Helper() f.common.Error(args...) @@ -91,7 +91,7 @@ func (f *F) Error(args ...interface{}) { // Errorf is equivalent to Logf followed by Fail. func (f *F) Errorf(format string, args ...interface{}) { if f.inFuzzFn { - panic("testing: f.Errorf was called inside the f.Fuzz function") + panic("testing: f.Errorf was called inside the f.Fuzz function, use t.Errorf instead") } f.common.Helper() f.common.Errorf(format, args...) @@ -100,7 +100,7 @@ func (f *F) Errorf(format string, args ...interface{}) { // Fail marks the function as having failed but continues execution. func (f *F) Fail() { if f.inFuzzFn { - panic("testing: f.Fail was called inside the f.Fuzz function") + panic("testing: f.Fail was called inside the f.Fuzz function, use t.Fail instead") } f.common.Helper() f.common.Fail() @@ -116,7 +116,7 @@ func (f *F) Fail() { // those other goroutines. func (f *F) FailNow() { if f.inFuzzFn { - panic("testing: f.FailNow was called inside the f.Fuzz function") + panic("testing: f.FailNow was called inside the f.Fuzz function, use t.FailNow instead") } f.common.Helper() f.common.FailNow() @@ -125,7 +125,7 @@ func (f *F) FailNow() { // Fatal is equivalent to Log followed by FailNow. func (f *F) Fatal(args ...interface{}) { if f.inFuzzFn { - panic("testing: f.Fatal was called inside the f.Fuzz function") + panic("testing: f.Fatal was called inside the f.Fuzz function, use t.Fatal instead") } f.common.Helper() f.common.Fatal(args...) @@ -134,7 +134,7 @@ func (f *F) Fatal(args ...interface{}) { // Fatalf is equivalent to Logf followed by FailNow. func (f *F) Fatalf(format string, args ...interface{}) { if f.inFuzzFn { - panic("testing: f.Fatalf was called inside the f.Fuzz function") + panic("testing: f.Fatalf was called inside the f.Fuzz function, use t.Fatalf instead") } f.common.Helper() f.common.Fatalf(format, args...) @@ -145,7 +145,7 @@ func (f *F) Fatalf(format string, args ...interface{}) { // Helper may be called simultaneously from multiple goroutines. func (f *F) Helper() { if f.inFuzzFn { - panic("testing: f.Helper was called inside the f.Fuzz function") + panic("testing: f.Helper was called inside the f.Fuzz function, use t.Helper instead") } // common.Helper is inlined here. @@ -171,7 +171,7 @@ func (f *F) Helper() { // Skip is equivalent to Log followed by SkipNow. func (f *F) Skip(args ...interface{}) { if f.inFuzzFn { - panic("testing: f.Skip was called inside the f.Fuzz function") + panic("testing: f.Skip was called inside the f.Fuzz function, use t.Skip instead") } f.common.Helper() f.common.Skip(args...) @@ -187,7 +187,7 @@ func (f *F) Skip(args ...interface{}) { // those other goroutines. func (f *F) SkipNow() { if f.inFuzzFn { - panic("testing: f.SkipNow was called inside the f.Fuzz function") + panic("testing: f.SkipNow was called inside the f.Fuzz function, use t.SkipNow instead") } f.common.Helper() f.common.SkipNow() @@ -196,7 +196,7 @@ func (f *F) SkipNow() { // Skipf is equivalent to Logf followed by SkipNow. func (f *F) Skipf(format string, args ...interface{}) { if f.inFuzzFn { - panic("testing: f.Skipf was called inside the f.Fuzz function") + panic("testing: f.Skipf was called inside the f.Fuzz function, use t.Skipf instead") } f.common.Helper() f.common.Skipf(format, args...) @@ -209,7 +209,7 @@ func (f *F) Skipf(format string, args ...interface{}) { // if the directory creation fails, TempDir terminates the test by calling Fatal. func (f *F) TempDir() string { if f.inFuzzFn { - panic("testing: f.TempDir was called inside the f.Fuzz function") + panic("testing: f.TempDir was called inside the f.Fuzz function, use t.TempDir instead") } f.common.Helper() return f.common.TempDir() @@ -299,6 +299,11 @@ func (f *F) Fuzz(ff interface{}) { // // TODO(jayconrod,katiehockman): dedupe testdata corpus with entries from f.Add // TODO(jayconrod,katiehockman): handle T.Parallel calls within fuzz function. + // TODO(jayconrod,katiehockman): improve output when running the subtest. + // e.g. instead of + // --- FAIL: FuzzSomethingError/#00 (0.00s) + // do + // --- FAIL: FuzzSomethingError/ (0.00s) run := func(e corpusEntry) error { if e.Values == nil { // Every code path should have already unmarshaled Data into Values. @@ -341,7 +346,7 @@ func (f *F) Fuzz(ff interface{}) { <-t.signal f.inFuzzFn = false if t.Failed() { - return errors.New(string(t.output)) + return errors.New(string(f.output)) } return nil } @@ -356,11 +361,12 @@ func (f *F) Fuzz(ff interface{}) { err := f.fuzzContext.coordinateFuzzing(*fuzzDuration, *parallel, f.corpus, types, corpusTargetDir, cacheTargetDir) if err != nil { f.result = FuzzResult{Error: err} - f.Error(err) + f.Fail() + fmt.Fprintf(f.w, "%v", err) if crashErr, ok := err.(fuzzCrashError); ok { crashName := crashErr.CrashName() - f.Logf("Crash written to %s", filepath.Join("testdata/corpus", f.name, crashName)) - f.Logf("To re-run:\ngo test %s -run=%s/%s", f.fuzzContext.importPath(), f.name, crashName) + fmt.Fprintf(f.w, "Crash written to %s\n", filepath.Join("testdata/corpus", f.name, crashName)) + fmt.Fprintf(f.w, "To re-run:\ngo test %s -run=%s/%s\n", f.fuzzContext.importPath(), f.name, crashName) } } // TODO(jayconrod,katiehockman): Aggregate statistics across workers @@ -377,7 +383,8 @@ func (f *F) Fuzz(ff interface{}) { } default: - // Fuzzing is not enabled. Only run the seed corpus. + // Fuzzing is not enabled, or will be done later. Only run the seed + // corpus now. for _, e := range f.corpus { run(e) } @@ -505,6 +512,9 @@ func runFuzzTargets(deps testDeps, fuzzTargets []InternalFuzzTarget) (ran, ok bo // If fuzzing is disabled (-test.fuzz is not set), runFuzzing // returns immediately. func runFuzzing(deps testDeps, fuzzTargets []InternalFuzzTarget) (ran, ok bool) { + // TODO(katiehockman,jayconrod): Should we do something special to make sure + // we don't print f.Log statements again with runFuzzing, since we already + // would have printed them when we ran runFuzzTargets (ie. seed corpus run)? if len(fuzzTargets) == 0 || *matchFuzz == "" { return false, true } diff --git a/src/testing/testing.go b/src/testing/testing.go index 2ad39f7137..2ba93ad63d 100644 --- a/src/testing/testing.go +++ b/src/testing/testing.go @@ -523,6 +523,7 @@ func (c *common) frameSkip(skip int) runtime.Frame { // and inserts the final newline if needed and indentation spaces for formatting. // This function must be called with c.mu held. func (c *common) decorate(s string, skip int) string { + // TODO(jayconrod,katiehockman): Consider refactoring the logging logic. // If more helper PCs have been added since we last did the conversion if c.helperNames == nil { c.helperNames = make(map[string]struct{})