Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

cmd/go: fuzzing output adjustments #48132

Closed
rsc opened this issue Sep 2, 2021 · 11 comments
Closed

cmd/go: fuzzing output adjustments #48132

rsc opened this issue Sep 2, 2021 · 11 comments
Labels
FrozenDueToAge fuzz Issues related to native fuzzing support NeedsFix The path to resolution is known, but the work has not been done. release-blocker
Milestone
Go1.18

Comments

@rsc
Copy link
Contributor

rsc commented Sep 2, 2021

The current chatty fuzzing output should be more amenable to processing with test2json. There are only minor changes needed:

  • It should start with a 'test beginning' header the same as when a regular test runs.
  • Having done that, the "fuzzing," prefix should probably be "fuzz:", and all the output lines should begin with that, to separate them from prints.
  • 'found a crash, minimizing...' should be 'fuzz: found a %d-byte crash input; minimizing'.

/cc @jayconrod @katiehockman
@rsc rsc added NeedsFix The path to resolution is known, but the work has not been done. release-blocker labels Sep 2, 2021
@rsc rsc added this to the Go1.18 milestone Sep 2, 2021
@rsc
Copy link
Contributor Author

rsc commented Sep 2, 2021

I see now that the header does happen with -v, just not without -v.
That is probably OK, since test2json requires -v.
But the other adjustments should still be applied.

@rsc rsc changed the title cmd/go: fuzzing output needs to be compatible with go tool test2json cmd/go: fuzzing output adjustments Sep 2, 2021
@rsc
Copy link
Contributor Author

rsc commented Sep 2, 2021

Watching the output more, it would help to use d.Round(1*time.Second).String() to format the elapsed duration d, instead of printing number of seconds. It gets tiring to do the mental math on lines like

fuzzing, elapsed: 1389.0s, execs: 67961175 (48928/sec), workers: 16, interesting: 334

Duration.String would say 23m9s instead.

@jayconrod jayconrod added the fuzz Issues related to native fuzzing support label Sep 9, 2021
@katiehockman katiehockman self-assigned this Sep 14, 2021
@gopherbot
Copy link

Change https://golang.org/cl/349970 mentions this issue: [dev.fuzz] internal: fuzzing output adjustments

@rsc
Copy link
Contributor Author

rsc commented Sep 20, 2021 •
edited

Thanks for the fixes. Looks like one was missed as far as the prefix:

gathering baseline coverage, elapsed: 0s, workers: 16, left: 4178

I would suggest making this a bit closer to the status messages, like

fuzz: elapsed: 0s, processing seed corpus: 0/4178 cases done

or something like that. I'm not sure what the 'left: 4178' means exactly, so the suggested rewrite may not be any good on that front. It seems like there should be a second one of those prints when it's completely done with the corpus, or whatever 'left: 0' would mean.

While I'm nitpicking:

fuzz: found a 52-byte crash input; minimizing...

would be more concise and I think equally clear as

fuzz: minimizing 52-byte crash input

(perhaps with the elapsed time as in the others?).

I'm also not sure about the word 'crash' here, since in my case they are t.Fail inputs. There is no actual crash.
I wonder if it should be 'failure input'.

Similarly, perhaps 'Crash written to ...' should be 'Failure input written to ...'

@rsc rsc reopened this Sep 20, 2021
@rsc
Copy link
Contributor Author

rsc commented Sep 20, 2021

And does the number of workers ever change? Maybe it should just be printed once instead of in every message?

fuzz: elapsed: 3m27s, execs: 32025801 (154712/sec), workers: 16, interesting: 3
fuzz: elapsed: 3m30s, execs: 32472170 (154626/sec), workers: 16, interesting: 3
fuzz: elapsed: 3m33s, execs: 32957605 (154728/sec), workers: 16, interesting: 3
fuzz: elapsed: 3m36s, execs: 33428733 (154761/sec), workers: 16, interesting: 3
fuzz: elapsed: 3m39s, execs: 33887371 (154734/sec), workers: 16, interesting: 3
fuzz: elapsed: 3m42s, execs: 34354633 (154749/sec), workers: 16, interesting: 3

@katiehockman
Copy link
Contributor

Looks like one was missed as far as the prefix:

Will fix this, and the other nits! 👍

And does the number of workers ever change? Maybe it should just be printed once instead of in every message?

Nope. We can probably just print it once at the start.

As for the use of "crash", that's the verbiage we've been using throughout our documentation and blog posts so far to indicating any kind of failure that is found during fuzzing. It's also something that's used in a lot of other documentation around the web about fuzzing (like libfuzzer's -minimize_crash flag). Is this something you feel really strongly about? Otherwise, I'd really prefer to keep it.

@katiehockman
Copy link
Contributor

fuzz: minimizing 52-byte crash input

@jayconrod suggested keeping the ... in a previous CL because it tells the user that something is in progress and they should wait. LMK if you disagree.

@gopherbot
Copy link

Change https://golang.org/cl/350997 mentions this issue: [dev.fuzz] internal/fuzz: more fuzzing output adjustments

@gopherbot
Copy link

Change https://golang.org/cl/351273 mentions this issue: [dev.fuzz] internal/fuzz: more fuzzing output adjustments

gopherbot pushed a commit that referenced this issue Sep 22, 2021
@katiehockman
[dev.fuzz] internal/fuzz: more fuzzing output adjustments
dc5b1d3 
This change also makes it so that non-recoverable errors (which should
be pretty rare) will no longer be minimized as these failures can be
flakier and harder to minimize successfully.

Updates #48132

Change-Id: I991d837993ea1fb0304b3ec491cc725ef5265652
Reviewed-on: https://go-review.googlesource.com/c/go/+/351273
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>
@rsc
Copy link
Contributor Author

rsc commented Sep 23, 2021

Thanks for the fixes. Using crasher is OK but we need to define it clearly in the docs (in package testing and also in reference docs), since it doesn't mean what it looks like.

@gopherbot
Copy link

Change https://go.dev/cl/443596 mentions this issue: testing: fix many test2json inaccuracies

gopherbot pushed a commit that referenced this issue Oct 26, 2022
@rsc @gopherbot
testing: fix many test2json inaccuracies
1c72ee7 
Test2json is parsing the output stream from the test, which includes
package testing's own framing lines intermingled with other output,
in particular any output printed via fmt.Printf, println, and so on.
We have had recurring problems with unexpected partial output lines
causing a framing line to be missed.

A recent talk at GopherCon gave an example of an integration test
involving Docker that happened to print \r-terminated lines instead
of \n-terminated lines in some configurations, which in turn broke
test2json badly. (https://www.gophercon.com/agenda/session/944259)

There are also a variety of open reported issues with similar problems,
which this CL also addresses. The general approach is to add a new
testing flag -test.v=json that means to print additional output to help
test2json. And then test2json takes advantage of that output.

Among the fixes:

 - Identify testing framing more reliably, using ^V
   (#23036, #26325, #43683, GopherCon talk)
 - Test that output with \r\n endings is handled correctly
   (#43683, #34286)
 - Use === RUN in fuzz tests (#52636, #48132)
 - Add === RUN lines to note benchmark starts (#27764, #49505)
 - Print subtest --- PASS/FAIL lines as they happen (#29811)
 - Add === NAME lines to emit more test change events,
   such as when a subtest stops and the parent continues running.
 - Fix event shown in overall test failure (#27568)
 - Avoid interleaving of writes to os.Stdout and os.Stderr (#33419)

Fixes #23036.
Fixes #26325.
Fixes #27568.
Fixes #27764.
Fixes #29811.
Fixes #33419.
Fixes #34286.
Fixes #43683.
Fixes #49505.
Fixes #52636.

Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6
Reviewed-on: https://go-review.googlesource.com/c/go/+/443596
Auto-Submit: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
romaindoumenc pushed a commit to TroutSoftware/go that referenced this issue Nov 3, 2022
@rsc @romaindoumenc
testing: fix many test2json inaccuracies
2955168 
Test2json is parsing the output stream from the test, which includes
package testing's own framing lines intermingled with other output,
in particular any output printed via fmt.Printf, println, and so on.
We have had recurring problems with unexpected partial output lines
causing a framing line to be missed.

A recent talk at GopherCon gave an example of an integration test
involving Docker that happened to print \r-terminated lines instead
of \n-terminated lines in some configurations, which in turn broke
test2json badly. (https://www.gophercon.com/agenda/session/944259)

There are also a variety of open reported issues with similar problems,
which this CL also addresses. The general approach is to add a new
testing flag -test.v=json that means to print additional output to help
test2json. And then test2json takes advantage of that output.

Among the fixes:

 - Identify testing framing more reliably, using ^V
   (golang#23036, golang#26325, golang#43683, GopherCon talk)
 - Test that output with \r\n endings is handled correctly
   (golang#43683, golang#34286)
 - Use === RUN in fuzz tests (golang#52636, golang#48132)
 - Add === RUN lines to note benchmark starts (golang#27764, golang#49505)
 - Print subtest --- PASS/FAIL lines as they happen (golang#29811)
 - Add === NAME lines to emit more test change events,
   such as when a subtest stops and the parent continues running.
 - Fix event shown in overall test failure (golang#27568)
 - Avoid interleaving of writes to os.Stdout and os.Stderr (golang#33419)

Fixes golang#23036.
Fixes golang#26325.
Fixes golang#27568.
Fixes golang#27764.
Fixes golang#29811.
Fixes golang#33419.
Fixes golang#34286.
Fixes golang#43683.
Fixes golang#49505.
Fixes golang#52636.

Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6
Reviewed-on: https://go-review.googlesource.com/c/go/+/443596
Auto-Submit: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
@golang golang locked and limited conversation to collaborators Oct 26, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge fuzz Issues related to native fuzzing support NeedsFix The path to resolution is known, but the work has not been done. release-blocker
Projects
Go Security
Status: No status
Milestone
Go1.18
Development

No branches or pull requests
4 participants
@rsc @jayconrod @gopherbot @katiehockman