diff --git a/src/cmd/go/testdata/script/test_fuzz_cov.txt b/src/cmd/go/testdata/script/test_fuzz_cov.txt index 05b634889f..e38912ba7c 100644 --- 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 fd3dad29b4..ca5f82a151 100644 --- 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...) +}