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>

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

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.debugLogf(
-							c.opts.Log,
+							"found crasher, id: %s, parent: %s, gen: %d, size: %d, exec time: %s",
-							"DEBUG new crasher, elapsed: %s, id: %s, parent: %s, gen: %d, size: %d, exec time: %s\n",
-							c.elapsed(),
 							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.debugLogf(
-							c.opts.Log,
+							"processed an initial input, id: %s, new bits: %d, size: %d, exec time: %s",
-							"DEBUG processed an initial input, elapsed: %s, id: %s, new bits: %d, size: %d, exec time: %s\n",
-							c.elapsed(),
 							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.debugLogf(
-								c.opts.Log,
+								"finished processing input corpus, entries: %d, initial coverage bits: %d",
-								"DEBUG finished processing input corpus, elapsed: %s, entries: %d, initial coverage bits: %d\n",
-								c.elapsed(),
 								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.debugLogf(
-								c.opts.Log,
+								"new interesting input, id: %s, parent: %s, gen: %d, new bits: %d, total bits: %d, size: %d, exec time: %s",
-								"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(),
 								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.debugLogf(
-							c.opts.Log,
+							"worker reported interesting input that doesn't expand coverage, id: %s, parent: %s, canMinimize: %t",
-							"DEBUG worker reported interesting input that doesn't expand coverage, elapsed: %s, id: %s, parent: %s, canMinimize: %t\n",
-							c.elapsed(),
 							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.debugLogf(
-							c.opts.Log,
+							"finished testing-only phase, entries: %d",
-							"DEBUG finished testing-only phase, elapsed: %s, entries: %d\n",
-							time.Since(c.startTime),
 							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...)
+}