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

Test cases passed but gotestsum print out Failed in summary #400

Open
khanhtc1202 opened this issue Apr 19, 2024 · 7 comments
Open

Test cases passed but gotestsum print out Failed in summary #400

khanhtc1202 opened this issue Apr 19, 2024 · 7 comments

Comments

@khanhtc1202
Copy link

khanhtc1202 commented Apr 19, 2024 •
edited
Loading

We tried to adopt gotestsum to https://github.com/karmada-io/karmada repo, and in both CI and local tests, the summary printed by gotestsum returned FAILED even when all test cases passed. Rerun test cases again using go test command and it passed normally.

This is the stdout printed by gotestsum in CI (Github Actions)
ref: https://github.com/karmada-io/karmada/actions/runs/8752542558/job/24020602781?pr=4850#step:4:8673

This is the stdout printed by gotestsum in the local

$ gotestsum -- -v -run=TestGetMinTolerationTime pkg/util/helper/*.go
✓  command-line-arguments (478ms)

=== Failed
=== FAIL: command-line-arguments TestGetMinTolerationTime (unknown)
-1ns=== RUN   TestGetMinTolerationTime/no_usedTolerations
0s=== RUN   TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations
59.999932917s=== RUN   TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil
-1ns=== RUN   TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil
-1ns=== RUN   TestGetMinTolerationTime/find_the_latest_trigger_time
59.999909167s=== RUN   TestGetMinTolerationTime/trigger_time_is_up
0s--- PASS: TestGetMinTolerationTime (0.00s)
    --- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)
    --- PASS: TestGetMinTolerationTime/no_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/find_the_latest_trigger_time (0.00s)
    --- PASS: TestGetMinTolerationTime/trigger_time_is_up (0.00s)

=== FAIL: command-line-arguments TestGetMinTolerationTime/no_noExecuteTaints (unknown)
-1ns=== RUN   TestGetMinTolerationTime/no_usedTolerations
0s=== RUN   TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations
59.999932917s=== RUN   TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil
-1ns=== RUN   TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil
-1ns=== RUN   TestGetMinTolerationTime/find_the_latest_trigger_time
59.999909167s=== RUN   TestGetMinTolerationTime/trigger_time_is_up
0s--- PASS: TestGetMinTolerationTime (0.00s)
    --- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)
    --- PASS: TestGetMinTolerationTime/no_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/find_the_latest_trigger_time (0.00s)
    --- PASS: TestGetMinTolerationTime/trigger_time_is_up (0.00s)

DONE 2 tests, 2 failures in 3.979s

gotestsum printed FAIL, while rerun using go test

$  go test -v -run=TestGetMinTolerationTime pkg/util/helper/*.go
=== RUN   TestGetMinTolerationTime
=== RUN   TestGetMinTolerationTime/no_noExecuteTaints
-1ns=== RUN   TestGetMinTolerationTime/no_usedTolerations
0s=== RUN   TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations
59.999899792s=== RUN   TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil
-1ns=== RUN   TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil
-1ns=== RUN   TestGetMinTolerationTime/find_the_latest_trigger_time
59.999854833s=== RUN   TestGetMinTolerationTime/trigger_time_is_up
0s--- PASS: TestGetMinTolerationTime (0.00s)
    --- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)
    --- PASS: TestGetMinTolerationTime/no_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/find_the_latest_trigger_time (0.00s)
    --- PASS: TestGetMinTolerationTime/trigger_time_is_up (0.00s)
PASS
ok  	command-line-arguments	0.477s

Is this something wrong with gotestsum or did I miss setting any flags?
@dnephin
Copy link
Member

dnephin commented Apr 19, 2024

Hello! FAIL: ... (unknown) indicates that https://pkg.go.dev/cmd/test2json (the tool used to parse test output into json) failed to parse the output and was missing a PASS line for that test. Due to the missing event gotestsum can't determine if the test passed or failed, so it reports FAIL as to not hide a potential failure.

Most of the time the problem is a missing newline in the output from the tests. You see can similar issues here: #105, #141, #124. And the upstream golang issue golang/go#38063, golang/go#57172

Are you by chance using a Go version older than 1.20 locally? It seems most of these issues were fixed in go1.20.

If that's not the case, you you share the output of go test -json -run=TestGetMinTolerationTime pkg/util/helper/*.go? That should help debug the problem.

@khanhtc1202
Copy link
Author

Thanks for quick response 😄 I'm using go version 1.21 so I think it could not cause the issue as you mentioned

$ go version
go version go1.21.8 darwin/arm64

Here is the output of the go test -json command in my local

$ go test -json -run=TestGetMinTolerationTime pkg/util/helper/*.go
{"Time":"2024-04-19T23:11:02.458912+07:00","Action":"start","Package":"command-line-arguments"}
{"Time":"2024-04-19T23:11:03.421969+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime"}
{"Time":"2024-04-19T23:11:03.422079+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime","Output":"=== RUN   TestGetMinTolerationTime\n"}
{"Time":"2024-04-19T23:11:03.422118+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints"}
{"Time":"2024-04-19T23:11:03.422127+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Output":"=== RUN   TestGetMinTolerationTime/no_noExecuteTaints\n"}
{"Time":"2024-04-19T23:11:03.422137+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Output":"-1ns"}
{"Time":"2024-04-19T23:11:03.422154+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Output":"--- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422161+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Elapsed":0}
{"Time":"2024-04-19T23:11:03.422164+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_usedTolerations"}
{"Time":"2024-04-19T23:11:03.422166+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_usedTolerations","Output":"=== RUN   TestGetMinTolerationTime/no_usedTolerations\n"}
{"Time":"2024-04-19T23:11:03.422168+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_usedTolerations","Output":"0s"}
{"Time":"2024-04-19T23:11:03.422266+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_usedTolerations","Output":"--- PASS: TestGetMinTolerationTime/no_usedTolerations (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422302+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_usedTolerations","Elapsed":0}
{"Time":"2024-04-19T23:11:03.422329+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations"}
{"Time":"2024-04-19T23:11:03.422364+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations","Output":"=== RUN   TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations\n"}
{"Time":"2024-04-19T23:11:03.422406+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations","Output":"59.999936625s"}
{"Time":"2024-04-19T23:11:03.422425+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations","Output":"--- PASS: TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422433+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations","Elapsed":0}
{"Time":"2024-04-19T23:11:03.422439+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil"}
{"Time":"2024-04-19T23:11:03.422444+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil","Output":"=== RUN   TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil\n"}
{"Time":"2024-04-19T23:11:03.42245+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil","Output":"-1ns"}
{"Time":"2024-04-19T23:11:03.422456+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil","Output":"--- PASS: TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422462+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil","Elapsed":0}
{"Time":"2024-04-19T23:11:03.422466+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil"}
{"Time":"2024-04-19T23:11:03.422784+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil","Output":"=== RUN   TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil\n"}
{"Time":"2024-04-19T23:11:03.422796+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil","Output":"-1ns"}
{"Time":"2024-04-19T23:11:03.422803+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil","Output":"--- PASS: TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422808+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil","Elapsed":0}
{"Time":"2024-04-19T23:11:03.422813+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/find_the_latest_trigger_time"}
{"Time":"2024-04-19T23:11:03.422818+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/find_the_latest_trigger_time","Output":"=== RUN   TestGetMinTolerationTime/find_the_latest_trigger_time\n"}
{"Time":"2024-04-19T23:11:03.422844+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/find_the_latest_trigger_time","Output":"59.999904792s"}
{"Time":"2024-04-19T23:11:03.422849+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/find_the_latest_trigger_time","Output":"--- PASS: TestGetMinTolerationTime/find_the_latest_trigger_time (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422852+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/find_the_latest_trigger_time","Elapsed":0}
{"Time":"2024-04-19T23:11:03.422854+07:00","Action":"run","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/trigger_time_is_up"}
{"Time":"2024-04-19T23:11:03.422856+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/trigger_time_is_up","Output":"=== RUN   TestGetMinTolerationTime/trigger_time_is_up\n"}
{"Time":"2024-04-19T23:11:03.42286+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/trigger_time_is_up","Output":"0s"}
{"Time":"2024-04-19T23:11:03.422862+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/trigger_time_is_up","Output":"--- PASS: TestGetMinTolerationTime/trigger_time_is_up (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422864+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/trigger_time_is_up","Elapsed":0}
{"Time":"2024-04-19T23:11:03.422866+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime","Output":"--- PASS: TestGetMinTolerationTime (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.423005+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime","Elapsed":0}
{"Time":"2024-04-19T23:11:03.423015+07:00","Action":"output","Package":"command-line-arguments","Output":"PASS\n"}
{"Time":"2024-04-19T23:11:03.423319+07:00","Action":"output","Package":"command-line-arguments","Output":"ok  \tcommand-line-arguments\t0.964s\n"}
{"Time":"2024-04-19T23:11:03.423358+07:00","Action":"pass","Package":"command-line-arguments","Elapsed":0.964}

@dnephin
Copy link
Member

dnephin commented Apr 19, 2024

I see an Action: pass in that output, and if I run this with the current main branch of gotestsum:

$ gotestsum -ftestname --raw-command cat example.json

I see the expected output (no failed tests). I'm not sure what is causing the unknown fail.

What is that -1ns output in the original post? Is that something from your shell?
Do you have the latest release of gotestsum installed locally?

@khanhtc1202
Copy link
Author

I used latest release of gotestsum v1.11.0 not the latest main branch code. Maybe that is the cause 👀

@khanhtc1202
Copy link
Author

khanhtc1202 commented Apr 20, 2024 •
edited
Loading

I tried to install gotestsum at latest commit (e9677fb) and look like nothing changed 🤔

$ go install gotest.tools/gotestsum@e9677fb405a5c0dc0b9d7217a7c73c3a20c5cb66
$ gotestsum -- -v -run=TestGetMinTolerationTime pkg/util/helper/*.go
✓  command-line-arguments (1.096s)

=== Failed
=== FAIL: command-line-arguments TestGetMinTolerationTime (unknown)
-1ns=== RUN   TestGetMinTolerationTime/no_usedTolerations
0s=== RUN   TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations
59.999939459s=== RUN   TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil
-1ns=== RUN   TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil
-1ns=== RUN   TestGetMinTolerationTime/find_the_latest_trigger_time
59.999909333s=== RUN   TestGetMinTolerationTime/trigger_time_is_up
0s--- PASS: TestGetMinTolerationTime (0.00s)
    --- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)
    --- PASS: TestGetMinTolerationTime/no_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/find_the_latest_trigger_time (0.00s)
    --- PASS: TestGetMinTolerationTime/trigger_time_is_up (0.00s)

=== FAIL: command-line-arguments TestGetMinTolerationTime/no_noExecuteTaints (unknown)
-1ns=== RUN   TestGetMinTolerationTime/no_usedTolerations
0s=== RUN   TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations
59.999939459s=== RUN   TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil
-1ns=== RUN   TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil
-1ns=== RUN   TestGetMinTolerationTime/find_the_latest_trigger_time
59.999909333s=== RUN   TestGetMinTolerationTime/trigger_time_is_up
0s--- PASS: TestGetMinTolerationTime (0.00s)
    --- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)
    --- PASS: TestGetMinTolerationTime/no_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations (0.00s)
    --- PASS: TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil (0.00s)
    --- PASS: TestGetMinTolerationTime/find_the_latest_trigger_time (0.00s)
    --- PASS: TestGetMinTolerationTime/trigger_time_is_up (0.00s)

DONE 2 tests, 2 failures in 5.804s

Also, I tried both zsh (my current shell) and bash but both printed out the -1ns Not sure what it is since go test command run on my local didn't print anything like that.

@khanhtc1202 khanhtc1202 mentioned this issue Apr 20, 2024
Closed
@khanhtc1202
Copy link
Author

khanhtc1202 commented Apr 20, 2024 •
edited
Loading

@dnephin I found that -1ns, it was a print statement in the test source code. Remove that line and the gotestsum can parse the JSON output as expected.

{"Time":"2024-04-19T23:11:03.422127+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Output":"=== RUN   TestGetMinTolerationTime/no_noExecuteTaints\n"}
{"Time":"2024-04-19T23:11:03.422137+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Output":"-1ns"}
{"Time":"2024-04-19T23:11:03.422154+07:00","Action":"output","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Output":"--- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)\n"}
{"Time":"2024-04-19T23:11:03.422161+07:00","Action":"pass","Package":"command-line-arguments","Test":"TestGetMinTolerationTime/no_noExecuteTaints","Elapsed":0}

previous

gotestsum -ftestname --raw-command cat examples.json              
PASS command-line-arguments.TestGetMinTolerationTime/no_noExecuteTaints (0.00s)
PASS command-line-arguments
=== RUN   TestGetMinTolerationTime
FAIL command-line-arguments.TestGetMinTolerationTime (-1.00s)

=== Failed
=== FAIL: command-line-arguments TestGetMinTolerationTime (unknown)
-1ns--- PASS: TestGetMinTolerationTime/no_noExecuteTaints (0.00s)

DONE 2 tests, 1 failure in 0.006s

now

gotestsum -ftestname --raw-command cat examples1.json 
PASS command-line-arguments.TestGetMinTolerationTime/no_noExecuteTaints (0.00s)
PASS command-line-arguments.TestGetMinTolerationTime/no_usedTolerations (0.00s)
PASS command-line-arguments.TestGetMinTolerationTime/with_noExecuteTaints_and_usedTolerations (0.00s)
PASS command-line-arguments.TestGetMinTolerationTime/usedTolerantion.TolerationSeconds_is_nil (0.00s)
PASS command-line-arguments.TestGetMinTolerationTime/noExecuteTaints.TimeAdded_is_nil (0.00s)
PASS command-line-arguments.TestGetMinTolerationTime/find_the_latest_trigger_time (0.00s)
PASS command-line-arguments.TestGetMinTolerationTime/trigger_time_is_up (0.00s)
PASS command-line-arguments.TestGetMinTolerationTime (0.00s)
PASS command-line-arguments

DONE 8 tests in 0.006s

I think we should update the gotestsum to accept something printout in stdout from the test source code (like that -1ns). WDYT?

Ofcource for this time, we can remove the print statement from the Karmada test code since it doesn't mean anything anyway.

@dnephin
Copy link
Member

dnephin commented May 30, 2024

I don't know exactly how that would work. I think the problem was missing newline in the output were confusing test2json. It's possible I don't understand the problem, but I'm glad it's working now!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dnephin @khanhtc1202