proposal: testing: more structured output from fuzz tests

[prototype0372]

Proposal Details

This is my first issue in the Go repo - if I miss something out please let me know and I'll add it. Furthermore, if this problem is solved then please point me in the right direction. TIA!

Problem to solve

Do some post-processing on fuzzing output as part of CI.

Current behaviour

There is a -json flag that may be passed for fuzz tests that does a fairly basic job of outputting the results of the test in a line-by-line json stream. For example

{"Time":"2024-06-19T14:53:25.086130955+01:00","Action":"run","Package":"example.com/foo/bar","Test":"FuzzFooBar"}
{"Time":"2024-06-19T14:53:25.086133564+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"=== RUN   FuzzFooBar\n"}
{"Time":"2024-06-19T14:53:25.098551229+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 0/112 completed\n"}
{"Time":"2024-06-19T14:53:25.308440206+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 112/112 completed, now fuzzing with 20 workers\n"}
{"Time":"2024-06-19T14:53:27.05786798+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"fuzz: elapsed: 2s, execs: 93141 (47539/sec), new interesting: 0 (total: 112)\n"}
{"Time":"2024-06-19T14:53:27.058004081+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"--- FAIL: FuzzFooBar (1.97s)\n"}
{"Time":"2024-06-19T14:53:27.0580113+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"    --- FAIL: FuzzFooBar (0.00s)\n"}
{"Time":"2024-06-19T14:53:27.058015058+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"        testing.go:1590: panic: =0\n"}
{"Time":"2024-06-19T14:53:27.058018557+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            goroutine 6081 [running]:\n"}
{"Time":"2024-06-19T14:53:27.058022151+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            runtime/debug.Stack()\n"}
{"Time":"2024-06-19T14:53:27.058025292+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/runtime/debug/stack.go:24 +0x9b\n"}
{"Time":"2024-06-19T14:53:27.058028825+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            testing.tRunner.func1()\n"}
{"Time":"2024-06-19T14:53:27.058031564+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/testing/testing.go:1590 +0x1c8\n"}
{"Time":"2024-06-19T14:53:27.058034268+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            panic({0x8a4a80?, 0xc007376420?})\n"}
{"Time":"2024-06-19T14:53:27.058037553+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/runtime/panic.go:770 +0x132\n"}
{"Time":"2024-06-19T14:53:27.058040183+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            example.com/foo/bar.parseFoo({0xc00731d195, 0x5}, 0x0)\n"}
{"Time":"2024-06-19T14:53:27.058042916+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/home/user/go/src/example.com/foo/bar/baz.go:81 +0x3aa\n"}
{"Time":"2024-06-19T14:53:27.058045831+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            example.com/foo/bar.FooBar({0xc00731d195?, 0x4?})\n"}
{"Time":"2024-06-19T14:53:27.058048718+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/home/user/go/src/example.com/foo/bar/baz.go:50 +0x3d\n"}
{"Time":"2024-06-19T14:53:27.058051449+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            example.com/foo/bar_test.FuzzFooBar.func1(0xc007402340, {0xc00731d195?, 0x0?})\n"}
{"Time":"2024-06-19T14:53:27.058056846+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/home/user/go/src/example.com/foo/bar/baz_test.go:209 +0x27\n"}
{"Time":"2024-06-19T14:53:27.058060045+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            reflect.Value.call({0x8a9a00?, 0x9502d0?, 0x13?}, {0x91e6ec, 0x4}, {0xc00737c6c0, 0x2, 0x2?})\n"}
{"Time":"2024-06-19T14:53:27.058063124+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/reflect/value.go:596 +0xca6\n"}
{"Time":"2024-06-19T14:53:27.058066795+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            reflect.Value.Call({0x8a9a00?, 0x9502d0?, 0x55686d?}, {0xc00737c6c0?, 0x91dba0?, 0xf?})\n"}
{"Time":"2024-06-19T14:53:27.058070343+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/reflect/value.go:380 +0xb9\n"}
{"Time":"2024-06-19T14:53:27.058073562+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            testing.(*F).Fuzz.func1.1(0xc007402340?)\n"}
{"Time":"2024-06-19T14:53:27.058094739+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/testing/fuzz.go:335 +0x325\n"}
{"Time":"2024-06-19T14:53:27.058117+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            testing.tRunner(0xc007402340, 0xc00734dd40)\n"}
{"Time":"2024-06-19T14:53:27.058125926+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/testing/testing.go:1689 +0xfb\n"}
{"Time":"2024-06-19T14:53:27.058131209+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            created by testing.(*F).Fuzz.func1 in goroutine 6\n"}
{"Time":"2024-06-19T14:53:27.058135749+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \t/snap/go/10630/src/testing/fuzz.go:322 +0x574\n"}
{"Time":"2024-06-19T14:53:27.058140371+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"            \n"}
{"Time":"2024-06-19T14:53:27.058146352+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"    \n"}
{"Time":"2024-06-19T14:53:27.05815182+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"    Failing input written to testdata/fuzz/FuzzFooBar/7cad059f4ce4e35f\n"}
{"Time":"2024-06-19T14:53:27.058156412+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"    To re-run:\n"}
{"Time":"2024-06-19T14:53:27.058160946+01:00","Action":"output","Package":"example.com/foo/bar","Test":"FuzzFooBar","Output":"    go test -run=FuzzFooBar/7cad059f4ce4e35f\n"}
{"Time":"2024-06-19T14:53:27.058167091+01:00","Action":"fail","Package":"example.com/foo/bar","Test":"FuzzFooBar","Elapsed":1.97}
{"Time":"2024-06-19T14:53:27.05818611+01:00","Action":"output","Package":"example.com/foo/bar","Output":"FAIL\n"}
{"Time":"2024-06-19T14:53:27.073721916+01:00","Action":"output","Package":"example.com/foo/bar","Output":"exit status 1\n"}
{"Time":"2024-06-19T14:53:27.073757334+01:00","Action":"output","Package":"example.com/foo/bar","Output":"FAIL\texample.com/foo/bar\t1.992s\n"}
{"Time":"2024-06-19T14:53:27.073765388+01:00","Action":"fail","Package":"example.com/foo/bar","Elapsed":1.9929999999999999}

The particular field I'm interested in is Output as this contains the really important information from a testers perspective. Currently this field is just a copy of whatever line would otherwise have been printed to stdout if -json had been omitted.

Current workarounds

It's not difficult to do some regex matching on the Output field to pull out the interesting information (full stacktrace and sha of the failing input), but it feels like there could be a better way. And I don't know whether the text on stdout is considered a stable API.

Proposal

Make this Output field a structured type, or add new structured fields so that post-processing is as easy as running some jq. Something as simple as

type FuzzFail struct {
    Stacktrace []string
    FailingInputSHA string
    FailingInput []byte
}

would be ideal. Even having the FailingInput []byte in there is optional since I can pull that information out from testdata/fuzz given the sha and test name.

[gabyhelp]

Similar Issues

• cmd/test2json: test2json doesn't print the final "pass" action if fuzz test is interrupted #53563
• cmd/go: test2json does not handle "=== FUZZ" #52636
• proposal: cmd/test2json: provide stderr flag for output #61856
• testing: fuzz funcs that panic print redundant stack frames #48885
• testing: timeout failure text attributed to irrelevant, passing test #67705
• cmd/go: minimization during fuzzing can print several redundant lines #48709
• cmd/go: go test -json has package output incorrectly attributed to the last test when a test panics #35180
• internal/fuzz: many data races when fuzzing trivial string input #48307
• proposal: testing: flush test output on timeout, panic or abort #25213
• cmd/go: -run= not working with fuzz subtest names #48149

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}