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.

Sign up for GitHub

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: test2json does not handle "=== FUZZ" #52636

Closed
dnephin opened this issue Apr 30, 2022 · 3 comments
Closed

cmd/go: test2json does not handle "=== FUZZ" #52636

dnephin opened this issue Apr 30, 2022 · 3 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.20

Comments

@dnephin
Copy link
Contributor

dnephin commented Apr 30, 2022

What version of Go are you using (go version)?

go version go1.18.1 linux/amd64

Does this issue reproduce with the latest release?

Yes

What did you do?

I wrote a fuzz test, and ran it with go test -json -fuzz Fuzz.

What did you expect to see?

I expected the JSON events for the fuzz output to have a Test name of FuzzParse. FuzzParse is the function that produced the output.

Example:

{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"=== FUZZ  FuzzParse\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 0/5 completed\n"}

What did you see instead?

When I run go test -fuzz Fuzz the output looks right:

fuzz: elapsed: 0s, gathering baseline coverage: 0/5 completed
failure while testing seed corpus entry: FuzzParse/0e71390066240fd73c5eb87f27bf9cf3839d45b41771f24dc1e9e9aed9830244
fuzz: elapsed: 0s, gathering baseline coverage: 4/5 completed
--- FAIL: FuzzParse (0.04s)
    --- FAIL: FuzzParse (0.00s)
        snowid_test.go:197: assertion failed: 1 (string) !=  (normalized string)

When I run with the -json flag to get test2json output (go test -json -fuzz Fuzz), the fuzz output is attributed to the wrong test. The Test field is TestParse/l_not_allowed (the last unit test that happened to run before fuzz started), instead of the expected "Test": "FuzzParse".

{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"=== FUZZ  FuzzParse\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 0/5 completed\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"failure while testing seed corpus entry: FuzzParse/0e71390066240fd73c5eb87f27bf9cf3839d45b41771f24dc1e9e9aed9830244\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 4/5 completed\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Elapsed":0}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse","Elapsed":0}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"--- FAIL: FuzzParse (0.04s)\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"    --- FAIL: FuzzParse (0.00s)\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"        snowid_test.go:197: assertion failed: 1 (string) !=  (normalized string)\n"}

Full output (with the Time field removed) in the details below.

{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestNewNode"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestNewNode","Output":"=== RUN   TestNewNode\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestNewNode","Output":"--- PASS: TestNewNode (0.00s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestNewNode","Elapsed":0}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestGenerateDuplicateID"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestGenerateDuplicateID","Output":"=== RUN   TestGenerateDuplicateID\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestGenerateDuplicateID","Output":"--- PASS: TestGenerateDuplicateID (0.24s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestGenerateDuplicateID","Elapsed":0.24}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestRace"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestRace","Output":"=== RUN   TestRace\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestRace","Output":"--- PASS: TestRace (0.00s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestRace","Elapsed":0}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestBase58"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestBase58","Output":"=== RUN   TestBase58\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestBase58","Output":"--- PASS: TestBase58 (0.00s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestBase58","Elapsed":0}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestParse"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse","Output":"=== RUN   TestParse\n"}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestParse/ok"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/ok","Output":"=== RUN   TestParse/ok\n"}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestParse/0_not_allowed"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/0_not_allowed","Output":"=== RUN   TestParse/0_not_allowed\n"}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestParse/I_not_allowed"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/I_not_allowed","Output":"=== RUN   TestParse/I_not_allowed\n"}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestParse/O_not_allowed"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/O_not_allowed","Output":"=== RUN   TestParse/O_not_allowed\n"}
{"Action":"run","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"=== RUN   TestParse/l_not_allowed\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse","Output":"--- PASS: TestParse (0.00s)\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/ok","Output":"    --- PASS: TestParse/ok (0.00s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse/ok","Elapsed":0}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/0_not_allowed","Output":"    --- PASS: TestParse/0_not_allowed (0.00s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse/0_not_allowed","Elapsed":0}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/I_not_allowed","Output":"    --- PASS: TestParse/I_not_allowed (0.00s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse/I_not_allowed","Elapsed":0}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/O_not_allowed","Output":"    --- PASS: TestParse/O_not_allowed (0.00s)\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse/O_not_allowed","Elapsed":0}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"    --- PASS: TestParse/l_not_allowed (0.00s)\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"=== FUZZ  FuzzParse\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 0/5 completed\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"failure while testing seed corpus entry: FuzzParse/0e71390066240fd73c5eb87f27bf9cf3839d45b41771f24dc1e9e9aed9830244\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 4/5 completed\n"}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse/l_not_allowed","Elapsed":0}
{"Action":"pass","Package":"github.com/dnephin/snowid","Test":"TestParse","Elapsed":0}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"--- FAIL: FuzzParse (0.04s)\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"    --- FAIL: FuzzParse (0.00s)\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"        snowid_test.go:197: assertion failed: 1 (string) !=  (normalized string)\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Output":"    \n"}
{"Action":"fail","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Elapsed":0}
{"Action":"fail","Package":"github.com/dnephin/snowid","Test":"FuzzParse","Elapsed":0.04}
{"Action":"output","Package":"github.com/dnephin/snowid","Output":"FAIL\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Output":"exit status 1\n"}
{"Action":"output","Package":"github.com/dnephin/snowid","Output":"FAIL\tgithub.com/dnephin/snowid\t0.287s\n"}
{"Action":"fail","Package":"github.com/dnephin/snowid","Elapsed":0.287}
@dnephin
Copy link
Contributor Author

dnephin commented Apr 30, 2022 •
edited

I'm guessing

go/src/cmd/internal/test2json/test2json.go

Lines 150 to 154 in 1930977

updates = [][]byte{
[]byte("=== RUN "),
[]byte("=== PAUSE "),
[]byte("=== CONT "),
}
needs to be updated to include === FUZZ. I'm not sure if anything else would need to change.

@dr2chase
Copy link
Contributor

dr2chase commented May 8, 2022

@rolandshoemaker can you give this a look?

@dr2chase dr2chase added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 8, 2022
@seankhliao seankhliao added this to the Unplanned milestone Aug 20, 2022
@dnephin dnephin changed the title cmd/go: -fuzz with -json attributes fuzz output to the wrong test cmd/go: test2json does not handle "=== FUZZ" Oct 6, 2022
@gopherbot
Copy link

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

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>
@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Nov 18, 2022
@dmitshur dmitshur modified the milestones: Unplanned, Go1.20 Nov 18, 2022
@golang golang locked and limited conversation to collaborators Nov 18, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.20
Development

No branches or pull requests
5 participants
@dnephin @dmitshur @dr2chase @gopherbot @seankhliao