[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 <katie@golang.org>
Run-TryBot: Katie Hockman <katie@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Jay Conrod <jayconrod@google.com>

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 bd9ce5c512efcc1f92351274b48a29ca550dd5f1..a143edda089db2f2a257384779f6d4d5a8d16c0a 100644 (file)
--- 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 70d76d6fc619f8055eb4505bc0143f7823e68ee8..3fe5aebbf47b1b5c6e26bdfa06ce3cb2ddbec278 100644 (file)
--- 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 c85537956643b44c72ffa913114b4ef901104b26..2a0754fdd7b283e9092dd834a05b97a176622d84 100644 (file)
--- 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/<hash> (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 2ad39f7137413f0f15d509522374a38e9447269a..2ba93ad63d357949ec2e333078a7b58d228ac827 100644 (file)
--- 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{})