testing: failure messages should be easier to find

[rogpeppe]

$ go version
go version devel go1.17-dc00dc6c6b Thu Jun 10 12:41:37 2021 +0000 linux/amd64

I've spent a lot of time poring over CI test output trying to find exactly why a given test has failed. Often the output of a high level test includes info-level logs that may end up very useful to determine the cause of failure but are just noise when looking for the actual failure message.

There is currently no easy way to distinguish between info-level and error-level messages which makes it hard to find the actual cause of a given failure. Often I end up editing the test output and excluding all lines that match some regular expression, ending up with a smaller number of candidate lines which include the culprit I'm searching for.

This is made harder by the fact that some failure messages are generated by calling T.Log and then T.Fail so it's not necessarily clear that the logged message represents a failure.

Perhaps we could include an extra action type in the JSON test output that represents a call to T.Fail or T.FailNow; for example:

{"Time":"2021-07-05T12:16:14.184591685Z","Action":"fail","Package":"example.com/foo","Test":"TestFoo"}

Perhaps the line we could also include a stack trace of the failure, making it easier for tooling to point directly to the offending code.

This doesn't help with regular non-JSON test output, but that's perhaps hard to fix without breaking people's expected test messages, though we could add a flag to enable an explicit "test failed here" output line.

[mknyszek]

@rogpeppe I'm honestly not sure who to CC on this issue, since https://dev.golang.org/owners isn't very well populated for the testing package. If you think this issue is important, it would probably get more visibility as a concrete proposal (though, perhaps you already knew that :)).

[rogpeppe]

@mknyszek I thought it might be good to discuss the issue before making a concrete proposal - for example, maybe it's only me that sees this as a problem, or maybe adding new Action types will break existing clients or...

[mknyszek]

That makes sense, I'm just honestly not sure who to loop in as part of gardening to get the discussion going.

[mvdan]

Adding the JSON test output line sounds like a good idea to me. I empathize with having to skim through huge test output files, though those are almost never JSON output directly.

This doesn't help with regular non-JSON test output, but that's perhaps hard to fix without breaking people's expected test messages, though we could add a flag to enable an explicit "test failed here" output line.

Worth noting that many CI systems support special output syntax for cases like these, such as https://docs.github.com/en/actions/reference/workflow-commands-for-github-actions#setting-an-error-message. I think they also tend to mix in some regex-based heuristics to automatically pick up errors with positions from common tools.

I wonder why we'd need a flag to opt into the "test failed here" information; that sounds generally useful, and shouldn't take much space.

[rogpeppe]

I wonder why we'd need a flag to opt into the "test failed here" information; that sounds generally useful, and shouldn't take much space.

My main concern is that it might end up looking odd and get complaints about unneeded verbosity.

[seankhliao]

62728 is an accepted proposal, i suppose we can close this as a dupe?