search

gotestyourself / gotestsum

'go test' runner with output optimized for humans, JUnit XML for CI integration, and a summary of the test results.
Apache License 2.0
1.99k stars 118 forks source link

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

Open khanhtc1202 opened 3 months ago

khanhtc1202 commented 3 months ago

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 commented 3 months ago

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 https://github.com/golang/go/issues/38063, https://github.com/golang/go/issues/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 commented 3 months ago

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 commented 3 months ago

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 commented 3 months ago

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

khanhtc1202 commented 3 months ago

I tried to install gotestsum at latest commit (e9677fb405a5c0dc0b9d7217a7c73c3a20c5cb66) 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 commented 3 months ago

@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 commented 1 month ago

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!