cmd/test2json: passing test sets action=output for every JSON log #43683
Labels
Milestone
Comments
seankhliao
added
the
NeedsInvestigation
|
I noticed a |
|
Change https://go.dev/cl/443596 mentions this issue: |
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
added
NeedsFix
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
I got the following JSON output from running test2json on Windows on a test in the minikube repo:
The text is as follows:
and the JSON output looks like this:
{"Time":"2021-01-12T22:33:05.5581262Z","Action":"output","Output":"?=== RUN TestScheduledStopWindows\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:124: (dbg) Run: ./minikube-windows-amd64.exe start -p scheduled-stop-20210112223103-14028 --memory=1900 --driver=docker\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:124: (dbg) Done: ./minikube-windows-amd64.exe start -p scheduled-stop-20210112223103-14028 --memory=1900 --driver=docker: (1m43.59599s)\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:133: (dbg) Run: ./minikube-windows-amd64.exe stop -p scheduled-stop-20210112223103-14028 --schedule 5m\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:133: (dbg) Done: ./minikube-windows-amd64.exe stop -p scheduled-stop-20210112223103-14028 --schedule 5m: (1.0094241s)\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:187: (dbg) Run: ./minikube-windows-amd64.exe status --format={{.TimeToStop}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:187: (dbg) Done: ./minikube-windows-amd64.exe status --format={{.TimeToStop}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028: (1.0416793s)\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:57: (dbg) Run: ./minikube-windows-amd64.exe ssh -p scheduled-stop-20210112223103-14028 -- sudo systemctl show minikube-scheduled-stop --no-page\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:133: (dbg) Run: ./minikube-windows-amd64.exe stop -p scheduled-stop-20210112223103-14028 --schedule 5s\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:172: (dbg) Run: ./minikube-windows-amd64.exe status --format={{.Host}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:172: (dbg) Non-zero exit: ./minikube-windows-amd64.exe status --format={{.Host}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028: exit status 3 (3.5232091s)\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" \r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" -- stdout --\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" \tError\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" \r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" -- /stdout --\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" ** stderr ** \r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" \tE0112 22:32:59.642786 8588 status.go:363] failed to get storage capacity of /var: NewSession: new client: new client: dial tcp 127.0.0.1:33167: connectex: No connection could be made because the target machine actively refused it.\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" \tE0112 22:32:59.644806 8588 status.go:235] status error: NewSession: new client: new client: dial tcp 127.0.0.1:33167: connectex: No connection could be made because the target machine actively refused it.\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" \r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" ** /stderr **\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:172: status error: exit status 3 (may be ok)\r\n"} {"Time":"2021-01-12T22:33:05.6121601Z","Action":"output","Output":" scheduled_stop_test.go:172: (dbg) Run: ./minikube-windows-amd64.exe status --format={{.Host}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" scheduled_stop_test.go:172: (dbg) Non-zero exit: ./minikube-windows-amd64.exe status --format={{.Host}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028: exit status 7 (420.2802ms)\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" \r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" -- stdout --\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" \tStopped\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" \r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" -- /stdout --\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" scheduled_stop_test.go:172: status error: exit status 7 (may be ok)\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" scheduled_stop_test.go:172: (dbg) Run: ./minikube-windows-amd64.exe status --format={{.TimeToStop}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" scheduled_stop_test.go:172: (dbg) Non-zero exit: ./minikube-windows-amd64.exe status --format={{.TimeToStop}} -p scheduled-stop-20210112223103-14028 -n scheduled-stop-20210112223103-14028: exit status 7 (387.0412ms)\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" \r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" -- stdout --\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" \tNonexistent\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" \r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" -- /stdout --\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" scheduled_stop_test.go:172: status error: exit status 7 (may be ok)\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" helpers_test.go:171: Cleaning up \"scheduled-stop-20210112223103-14028\" profile ...\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" helpers_test.go:172: (dbg) Run: ./minikube-windows-amd64.exe delete -p scheduled-stop-20210112223103-14028\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Output":" helpers_test.go:172: (dbg) Done: ./minikube-windows-amd64.exe delete -p scheduled-stop-20210112223103-14028: (3.4373944s)\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Test":"TestScheduledStopWindows","Output":"--- PASS: TestScheduledStopWindows (121.44s)\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Test":"TestScheduledStopWindows","Output":"PASS\r\n"} {"Time":"2021-01-12T22:33:05.6131428Z","Action":"output","Test":"TestScheduledStopWindows","Output":"Tests completed in 2m1.4388647s (result code 0)\r\n"}I can't parse the data correctly because
action=outputfor every log line, and I'm trying to determine if the test has failed or passed. Weirdly, the tool works fine for other tests in the same repo. I was wondering if anybody else had encountered this or had any suggestions.I've included a sample .txt file from an integration test in the repo that seems to be working:
Thank you!
Go version: go version go1.15.5 windows/amd64
Exact command run:
The text was updated successfully, but these errors were encountered: