Skip to content

Commit

Permalink
internal/fuzz: improve debugging messages
Browse files Browse the repository at this point in the history 
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>
  • Loading branch information
@rolandshoemaker @gopherbot
rolandshoemaker authored and gopherbot committed Mar 15, 2023
1 parent 2d84fbb commit 70308d1
Show file tree
Hide file tree
Showing 2 changed files with 47 additions and 26 deletions.
5 changes: 4 additions & 1 deletion src/cmd/go/testdata/script/test_fuzz_cov.txt
View file
Expand Up @@ -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 --
Expand Down
68 changes: 43 additions & 25 deletions src/internal/fuzz/fuzz.go
View file
Expand Up @@ -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
Expand Down Expand Up @@ -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.
Expand All @@ -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,
Expand All @@ -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),
Expand All @@ -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),
)
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand All @@ -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),
)
}
Expand Down Expand Up @@ -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()
}
Expand Down Expand Up @@ -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...)
}

0 comments on commit 70308d1

Please sign in to comment.