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

testing: stdout output with no newline produces confusing/corrupt -v output #26325

Closed
neild opened this issue Jul 11, 2018 · 13 comments
Closed
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@neild
Copy link
Contributor

neild commented Jul 11, 2018

package out_test

import (
	"fmt"
	"testing"
)

func TestOut(t *testing.T) { fmt.Print("TestOut") }
$ go test .
ok  	testout	0.016s
$ go test . -v
=== RUN   TestOut
Test--- PASS: TestOut (0.00s)
PASS
ok  	testout	0.017s

Output to stdout during tests is captured and printed along with t.Logf et al. output when -v is supplied. If the output doesn't end with a newline, the output is as above.

We have some tools that parse test output which get confused in this situation. It's easy enough to avoid (just print a newline in your test) but it would also be pretty trivial for the testing package could add a newline when one is missing.

@ianlancetaylor ianlancetaylor added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 11, 2018
@ianlancetaylor ianlancetaylor added this to the Go1.12 milestone Jul 11, 2018
@mvdan
Copy link
Member

mvdan commented Jul 11, 2018

This does seem like something to fix, but note that you should be running go test -json to parse the test results.

@agnivade
Copy link
Contributor

There are some tools like https://github.com/rakyll/gotest which parses command line go test output. This will break those I believe.

@mvdan
Copy link
Member

mvdan commented Jul 11, 2018

The plaintext output has already been changed in the past, for example in 3a8b9cf. And now that there is go test -json, I'd imagine that it's less of a problem to make small changes to the plaintext output.

@neild
Copy link
Contributor Author

neild commented Jul 11, 2018

I don't think we should change anything other than, possibly, adding a newline at the end of the test output when one isn't present. I'd be surprised if anything depends on the current behavior. e.g., https://github.com/rakyll/gotest will fail to parse test output that doesn't end in a newline.

I actually didn't know about go test -json! That's definitely a better approach for automated parsing. I lean towards saying we should add that missing newline in the text output anyway when needed; I can't imagine anyone actually wants to see the output in the example above.

@neild
Copy link
Contributor Author

neild commented Jul 11, 2018

Heh. So it turns out go test -json works by parsing the normal text output...and it gets just as confused by this case.

{"Time":"2018-07-11T09:30:22.855058114-07:00","Action":"run","Package":"_/tmp/testout","Test":"TestOut"}
{"Time":"2018-07-11T09:30:22.855222613-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"=== RUN   TestOut\n"}
{"Time":"2018-07-11T09:30:22.855255176-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"Out--- PASS: TestOut (0.00s)\n"}
{"Time":"2018-07-11T09:30:22.855268402-07:00","Action":"output","Package":"_/tmp/testout","Output":"PASS\n"}
{"Time":"2018-07-11T09:30:22.855331884-07:00","Action":"output","Package":"_/tmp/testout","Output":"ok  \t_/tmp/testout\t0.011s\n"}
{"Time":"2018-07-11T09:30:22.856056764-07:00","Action":"pass","Package":"_/tmp/testout","Elapsed":0.012}

Contrast to the same test with a newline in the output, which correctly includes a "pass" action for the TestOut test:

{"Time":"2018-07-11T09:30:54.037472791-07:00","Action":"run","Package":"_/tmp/testout","Test":"TestOut"}
{"Time":"2018-07-11T09:30:54.037651722-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"=== RUN   TestOut\n"}
{"Time":"2018-07-11T09:30:54.037666684-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"Out\n"}
{"Time":"2018-07-11T09:30:54.037685506-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"--- PASS: TestOut (0.00s)\n"}
{"Time":"2018-07-11T09:30:54.037695155-07:00","Action":"pass","Package":"_/tmp/testout","Test":"TestOut","Elapsed":0}
{"Time":"2018-07-11T09:30:54.037708614-07:00","Action":"output","Package":"_/tmp/testout","Output":"PASS\n"}
{"Time":"2018-07-11T09:30:54.037761824-07:00","Action":"output","Package":"_/tmp/testout","Output":"ok  \t_/tmp/testout\t0.011s\n"}
{"Time":"2018-07-11T09:30:54.038279369-07:00","Action":"pass","Package":"_/tmp/testout","Elapsed":0.011}

@suzmue
Copy link
Contributor

suzmue commented Jul 14, 2021

Could the start of the line requirement be removed when parsing the output?

This will introduce new false positives, but the current implementation is not protected from false positives if the program prints a matching string to os.Stdout.

The consumers of go test -json are likely tools, which could also be built to handle multiple "pass"/"fail"/"skip" events and update its status if it receives more than one (eg the last one is the result). Sending too few events prevents tools from recovering without having to parse every output themselves, which defeats the point of using go test -json.

This does not address the issues with interleaving output presented in other issues, but is an easy change that does not prevent fixing these other changes in the future.

@jayconrod
Copy link
Contributor

+1 to @suzmue's suggestion, we should look at whether this is feasible.

We're always going to have false positives and negatives parsing test output, as long as test messages are sent on os.Stdout with arbitrary user data. If we drop the requirement for starting newlines, that seems like a better point on the tradeoff than when we are now though.

@junedev
Copy link

junedev commented Feb 7, 2022

We at exercism.org (official GoBridge/GDN mentoring platform) are also affected by this bug. Students can solve Go exercises in a web editor and we run their solutions against a set of test cases on a server and present them the results. For debugging, they can add fmt.Print... statements. Currently, if they don't use Println and no trailing line break, they don't get any proper test results because the JSON we are trying to parse for that part of the code does not make sense anymore.

TLDR: +1 for @suzmue's suggestion

@MisterSquishy
Copy link

we should look at whether this is feasible.

@jayconrod is this being done? is there any way i can help move it forward? this issue is making it extremely difficult to understand test failures in one of my projects.

i threw together a POC; it may be oversimplified but it seems like it'd be fairly straightforward to implement this change, and it would benefit a lot of folks.

@suzmue
Copy link
Contributor

suzmue commented Jun 22, 2022

No one is currently working on this, but I believe we would accept a CL for this fix.

cc @bcmills

@MisterSquishy
Copy link

👍 ill get my change polished up and submit a PR in the next couple of days

@gopherbot
Copy link

Change https://go.dev/cl/413616 mentions this issue: cmd/test2json: parse entire output lines for pass/fail/other update messages

@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
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 modified the milestones: Backlog, Go1.20 Nov 18, 2022
@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
@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.
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

Successfully merging a pull request may close this issue.