proposal: testing: print more information about failing tests at the end

[josharian]

Proposal Details

If you run a bunch of tests (go test -v ./...), and something goes wrong, the end of the output typically looks like:

PASS
ok  	some/package/or/another	0.004s
FAIL

That final FAIL provides only a single bit of information. You then need to trawl though all the previous output to figure out which test in which package failed. This can be really painful. It's often in CI, which has a poor interface for managing the logs. And grepping isn't necessarily enough. For the output I'm staring at right now, there are 28 matches for "fail", of which only one is relevant.

I propose that on test failure, the go tool print a reprise/summary of failing tests alongside their packages. (Not for json output, of course.) Maybe something like:

PASS
ok  	some/package/or/another	0.004s
FAIL

FAILING TESTS
    --- FAIL: TestFoo (1.30s)
FAIL	package/with/bug	1.310s
    --- FAIL: TestBar (0.50s)
    --- FAIL: TestBaz/Quxx (0.02s)
FAIL	another/buggy/package	8.310s

Or some such? I'm not particular. All I really want is to be able to instantly tell at a glance what happened, with enough information that subsequent searches through the logs can take me directly to the problem(s).

[FiloSottile]

I definitely felt the same pain.

A question is whether to also re-print the test output. In -v mode that would be useful, without -v it would be basically the same output as above. Maybe we should re-print it only with -v? Or maybe the whole thing should only be enabled on -v?

[mateusz834]

Also worth noting is that with -v and parallel tests you get:

[mateusz@arch aaa ]$ go test -v .
=== RUN   TestOne
=== PAUSE TestOne
=== RUN   TestTwo
=== PAUSE TestTwo
=== RUN   TestThree
=== PAUSE TestThree
=== CONT  TestOne
    main_test.go:10: one
=== CONT  TestThree
    main_test.go:24: three
=== CONT  TestTwo
    main_test.go:17: two
=== NAME  TestOne
    main_test.go:12: one
=== NAME  TestThree
    main_test.go:26: three
--- PASS: TestOne (1.00s)
=== NAME  TestTwo
    main_test.go:19: two
--- PASS: TestTwo (1.00s)
--- PASS: TestThree (1.00s)
PASS
ok  	aaa	1.003s

Which is unreadable, it would be nice if it grouped this at the end.

[seankhliao]

#27755 points to -json and letting addition processes filter the output (e.g. gotestsum)
#30507 originally proposed having counts of passes/fails, but that was reduced to just a pass/fail.
#41748 looks like the same as this, but withdrawn
#41878 is about letting TestMain print the summary

especially in ci, it seems worth it to use additional tooling to process the results, rather than look at raw logs.

[josharian]

@seankhliao thanks for the pointers. Nothing I see there particularly changes how I feel about this.

letting TestMain print the summary

Note that TestMain is only for a single package. This pain is most acute when running across many packages.

especially in ci, it seems worth it to use additional tooling to process the results, rather than look at raw logs.

Respectfully, I strongly disagree. I don't want to have to pull in additional tools to make my tools usable. This is not an obscure use case. I want my tools to be helpful, out of the box. And I want this locally as well as in CI.

This is one of those pain points I've been very frustrated about for ages, and today just happened to be the first day that I realized, "wait, it doesn't have to be like this".

[seankhliao]

Having seen some very verbose output in tests with -v mostly from logger output, I have the feeling that it's just incompatible with clear/concise output.
The various CI providers all provide better navigation like showing just the output for specific (failing) tests.

The output here is like asking it to print the test results again, but without -v.
I'd think the better way to get that is to just run without -v in the first place?

[josharian]

I'd think the better way to get that is to just run without -v in the first place?

Running without -v leaves you with limited information on test failure, information that cannot always be regenerated by re-running (think flaky tests). Plus in a CI environment it seems kinda crazy to recommend running both with -v (for debugging details) and without -v (so you can easily tell what is failing).

I have the feeling that it's just incompatible with clear/concise output.

I think that a list of failing tests, along with the packages they are in, would be quite clear and concise.

The various CI providers all provide better navigation like showing just the output for specific (failing) tests.

Where is this for GitHub Actions?

(Where is it in my terminal?)

[earthboundkid]

#64576 has a similar motivation.

I am also frequently annoyed by this. It would save a lot of scrollback time to just list the failing tests briefly at the end.

[ayuhito]

gotestsum is a fairly popular userland package for this that might be able to inspire the final formatting for this proposal? In particular the pkgname format with skipped and failed elements printed at the end.

cc @dnephin

[dnephin]

I wrote gotestsum to address exactly these problems.

I'd say the key points are:

1. A summary line with count of tests run, tests failed, and tests skipped
2. Reprinting the output of any failed tests so that failures are easy to find.
3. Also reprinting the output of skipped tests. The existing go test output makes it way to easy to miss that tests are being skipped.

Once that was in place it was easy to add all the other features, Junit XML output, --watch for auto-running tests in the current package on file save during local development, etc.

I agree these things are just as valuable when tests are run locally as they are for CI.

Arguably the JUnit XML output and the option to send the full test2json output to a file, while printing a more compact format to stdout, are better features for CI integration. Many CI systems can take that output and give a better view of the failures.