internal/fuzz: improve debugging messages

Also enable debugging information in TestScript/test_fuzz_cov, which
hits a deadlock on builders, but I am unable to trigger locally. This
should make it somewhat easier to track down where the issue actually
is.

Updates #51484

Change-Id: I98124f862242798f2d9eba15cacefbd02924cfe2
Reviewed-on: https://go-review.googlesource.com/c/go/+/476595
Auto-Submit: Roland Shoemaker <roland@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Roland Shoemaker <roland@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>

diff --git a/src/cmd/go/testdata/script/test_fuzz_cov.txt b/src/cmd/go/testdata/script/test_fuzz_cov.txt
index 05b634889f335ee3b273d7dc2b0d49a3b4ed488c..e38912ba7c672acd422cf1b284f60461e19de3cc 100644 (file)
--- a/src/cmd/go/testdata/script/test_fuzz_cov.txt
+++ b/src/cmd/go/testdata/script/test_fuzz_cov.txt
@@ -5,7 +5,10 @@
 [short] skip
 [!fuzz-instrumented] skip
 
-! go test -fuzz=FuzzCov
+# TODO(#51484): enabled debugging info to help diagnose a deadlock in the fuzzer
+env GODEBUG=fuzzdebug=1
+go clean --fuzzcache
+! go test -fuzz=FuzzCov -v
 ! stderr 'cov instrumentation working'
 
 -- go.mod --

diff --git a/src/internal/fuzz/fuzz.go b/src/internal/fuzz/fuzz.go
index fd3dad29b4117a22794115737e0c3f1ef761514c..ca5f82a1515ef793641f35d48b9a64b764e60913 100644 (file)
--- a/src/internal/fuzz/fuzz.go
+++ b/src/internal/fuzz/fuzz.go
@@ -117,6 +117,15 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
        var fuzzErr error
        stopping := false
        stop := func(err error) {
+               if shouldPrintDebugInfo() {
+                       _, file, line, ok := runtime.Caller(1)
+                       if ok {
+                               c.debugLogf("stop called at %s:%d. stopping: %t", file, line, stopping)
+                       } else {
+                               c.debugLogf("stop called at unknown. stopping: %t", stopping)
+                       }
+               }
+
                if err == fuzzCtx.Err() || isInterruptError(err) {
                        // Suppress cancellation errors and terminations due to SIGINT.
                        // The messages are not helpful since either the user triggered the error
@@ -244,6 +253,9 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        if c.crashMinimizing != nil {
                                                // This crash is not minimized, and another crash is being minimized.
                                                // Ignore this one and wait for the other one to finish.
+                                               if shouldPrintDebugInfo() {
+                                                       c.debugLogf("found unminimized crasher, skipping in favor of minimizable crasher")
+                                               }
                                                break
                                        }
                                        // Found a crasher but haven't yet attempted to minimize it.
@@ -264,10 +276,8 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                }
                                        }
                                        if shouldPrintDebugInfo() {
-                                               fmt.Fprintf(
-                                                       c.opts.Log,
-                                                       "DEBUG new crasher, elapsed: %s, id: %s, parent: %s, gen: %d, size: %d, exec time: %s\n",
-                                                       c.elapsed(),
+                                               c.debugLogf(
+                                                       "found crasher, id: %s, parent: %s, gen: %d, size: %d, exec time: %s",
                                                        result.entry.Path,
                                                        result.entry.Parent,
                                                        result.entry.Generation,
@@ -280,10 +290,8 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                        } else if result.coverageData != nil {
                                if c.warmupRun() {
                                        if shouldPrintDebugInfo() {
-                                               fmt.Fprintf(
-                                                       c.opts.Log,
-                                                       "DEBUG processed an initial input, elapsed: %s, id: %s, new bits: %d, size: %d, exec time: %s\n",
-                                                       c.elapsed(),
+                                               c.debugLogf(
+                                                       "processed an initial input, id: %s, new bits: %d, size: %d, exec time: %s",
                                                        result.entry.Parent,
                                                        countBits(diffCoverage(c.coverageMask, result.coverageData)),
                                                        len(result.entry.Data),
@@ -295,10 +303,8 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        if c.warmupInputLeft == 0 {
                                                fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, gathering baseline coverage: %d/%d completed, now fuzzing with %d workers\n", c.elapsed(), c.warmupInputCount, c.warmupInputCount, c.opts.Parallel)
                                                if shouldPrintDebugInfo() {
-                                                       fmt.Fprintf(
-                                                               c.opts.Log,
-                                                               "DEBUG finished processing input corpus, elapsed: %s, entries: %d, initial coverage bits: %d\n",
-                                                               c.elapsed(),
+                                                       c.debugLogf(
+                                                               "finished processing input corpus, entries: %d, initial coverage bits: %d",
                                                                len(c.corpus.entries),
                                                                countBits(c.coverageMask),
                                                        )
@@ -327,16 +333,20 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                        break
                                                }
                                                if !entryNew {
-                                                       continue
+                                                       if shouldPrintDebugInfo() {
+                                                               c.debugLogf(
+                                                                       "ignoring duplicate input which increased coverage, id: %s",
+                                                                       result.entry.Path,
+                                                               )
+                                                       }
+                                                       break
                                                }
                                                c.updateCoverage(keepCoverage)
                                                c.inputQueue.enqueue(result.entry)
                                                c.interestingCount++
                                                if shouldPrintDebugInfo() {
-                                                       fmt.Fprintf(
-                                                               c.opts.Log,
-                                                               "DEBUG new interesting input, elapsed: %s, id: %s, parent: %s, gen: %d, new bits: %d, total bits: %d, size: %d, exec time: %s\n",
-                                                               c.elapsed(),
+                                                       c.debugLogf(
+                                                               "new interesting input, id: %s, parent: %s, gen: %d, new bits: %d, total bits: %d, size: %d, exec time: %s",
                                                                result.entry.Path,
                                                                result.entry.Parent,
                                                                result.entry.Generation,
@@ -349,10 +359,8 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        }
                                } else {
                                        if shouldPrintDebugInfo() {
-                                               fmt.Fprintf(
-                                                       c.opts.Log,
-                                                       "DEBUG worker reported interesting input that doesn't expand coverage, elapsed: %s, id: %s, parent: %s, canMinimize: %t\n",
-                                                       c.elapsed(),
+                                               c.debugLogf(
+                                                       "worker reported interesting input that doesn't expand coverage, id: %s, parent: %s, canMinimize: %t",
                                                        result.entry.Path,
                                                        result.entry.Parent,
                                                        result.canMinimize,
@@ -366,10 +374,8 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                if c.warmupInputLeft == 0 {
                                        fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, testing seed corpus: %d/%d completed, now fuzzing with %d workers\n", c.elapsed(), c.warmupInputCount, c.warmupInputCount, c.opts.Parallel)
                                        if shouldPrintDebugInfo() {
-                                               fmt.Fprintf(
-                                                       c.opts.Log,
-                                                       "DEBUG finished testing-only phase, elapsed: %s, entries: %d\n",
-                                                       time.Since(c.startTime),
+                                               c.debugLogf(
+                                                       "finished testing-only phase, entries: %d",
                                                        len(c.corpus.entries),
                                                )
                                        }
@@ -814,6 +820,13 @@ func (c *coordinator) refillInputQueue() {
 // queueForMinimization creates a fuzzMinimizeInput from result and adds it
 // to the minimization queue to be sent to workers.
 func (c *coordinator) queueForMinimization(result fuzzResult, keepCoverage []byte) {
+       if shouldPrintDebugInfo() {
+               c.debugLogf(
+                       "queueing input for minimization, id: %s, crasher: %t",
+                       result.entry.Path,
+                       result.crasherMsg != "",
+               )
+       }
        if result.crasherMsg != "" {
                c.minimizeQueue.clear()
        }
@@ -1081,3 +1094,8 @@ var debugInfo = godebug.New("fuzzdebug").Value() == "1"
 func shouldPrintDebugInfo() bool {
        return debugInfo
 }
+
+func (c *coordinator) debugLogf(format string, args ...any) {
+       t := time.Now().Format("2006-01-02 15:04:05.999999999")
+       fmt.Fprintf(c.opts.Log, t+" DEBUG "+format+"\n", args...)
+}