"go test": common prefix for errors

[Patrick Ohly]

Hello!

In Kubernetes, we have extensive infrastructure for collecting test failures. For "go test" based tests (unit tests, integration tests) we use gotest.tools/gotestsum to convert the output to a JUnit file for post-processing.

This approach has one drawback (https://github.com/kubernetes/kubernetes/issues/116402): the entire output of a failed tests is treated as the (in JUnit terminology) failure message. In particular for integration tests that also includes normal log output. The tool which triages failures then fails to detect that all of these test runs failed for the same reason because the "failure message" is too different for each run.

My initial reaction was that we should modify our tests so that each `t.Error` call uses a message with a unique prefix ("[FAILED]"). Then we could identify those failures during post-processing.

But this is going to be cumbersome to do and enforce, in particular when there are additional third-party helpers involved. It would be much easier if we could do `go test -failure-prefix [FAILED]` and then get that prefix injected automatically into all calls which combine logging with `t.Fail`. Would something like this be acceptable?

I'm aware that a test could do `t.Log("I failed."); t.Fail()`. But this should be rare and could be treated like it is now by the post-processing (i.e. failure without a specific failure message).

Bye, Patrick

[Ian Lance Taylor]

Maybe I'm missing something, but I would expect that this general
class of things would be addressed via "go test -json", and a program
that parses the JSON output as you desire.

Ian

[Patrick Ohly]

JSON output doesn't help. There's no indication there either that a certain message is a test failure. That's because t.Error = t.Log + t.Fail. Attached is an example.

Bye,  Patrick

[Jason E. Aten]

Perhaps the -v flag to "go test" would be helpful here, as in "go test -v".

[Patrick Ohly]

"-v" only changes how the result is presented. It doesn't change the result itself, i.e. it remains unclear which log message indicates the actual failure inside the test.

[Sean Liao]

implementing a helper/wrapper on your side might be easier, I believe most helpers take the TB interface rather than the concrete T type.

also it sounds more like a failure of the application to separate its output streams properly.

[Patrick Ohly]

The underlying problem is that a "go test" only has one output stream: the text written via `T.Log`. Additional output on stdout or stderr isn't associated with the test that produced it, which is bad when running tests in parallel or when running without "go test -v".

[mspre...@gmail.com]

With contextual logging, do we now have a better pattern easily available? Associate with the context a Logger that goes to T.Log?

[Patrick Ohly]

> Associate with the context a Logger that goes to T.Log?

That is indeed the approach taken in https://pkg.go.dev/k8s.io/klog/v2/ktesting for contextual logging with go-logr.

https://pkg.go.dev/golang.org/x/exp/slog doesn't have anything for it at the moment, at least not out-of-the-box.

The problem is that every single test needs to be modified for it to work. I was hoping to avoid that for `t.Error`, but given the reactions so far, that's probably what we'll have to do. Perhaps I'll write a code generator which wraps `KTestFoo([ctx *context.Context, ]t testing.TB)` in a generated `TestFoo(t *testing.T)`.

[Andrew Harris]

I'm not sure I completely grasp the use case here in detail, but FWIW, I explored collation of log lines per-test with https://pkg.go.dev/golang.org/x/exp/slog a while ago and ended up with a struct that implements both testing.TB and slog.Handler. The idea was:

(1) testing.TB methods that log, write to a buffer (Error/f, Fatal/f, Log/f, Skip/f) - the calls can be made into slog records, even

(2) slog.Handler methods write to the same buffer - so, the instance can just be passed to some code under test that slogs

(3) the buffer dumps to test output when a test failure with Error/f or Fatal/f is seen

If the goal is getting a nice sequence of just the relevant log lines leading to a test failure, this is feasible for independently executing tests.

If there is crosstalk between parallel tests, this isn't sufficient - structured logging maybe makes the problem easier but it's not trivial.