[go-nuts] redirecting log output into testing.T.Log
Hello! I'm working on logging in Kubernetes. One of the problems there is that all log output goes through a global logger in the k8s.io/klog package, which writes to stderr. When such code runs in a unit test, that additional output is not associated with the currently running unit test, so the output of `go test` for a failed test case is usually not helpful. It gets even worse when running tests in parallel. I have a proposal pending for Kubernetes for doing logging via a go-logr/logr.Logger and how to pass that logger instance around through the code base. During tests, each test function then can create such a Logger that writes via t.Log and `go test` output becomes more useful. The actual code that goes into binaries is the same, it just uses different Logger implementations. The downside is that tests have to be modified to set up such per-test log output. I don't see any other way of doing that, though, because the t instance of a test is by definition specific to each test function and therefore only that function can create the logger and then pass it on. If it was done by some kind of test driver, then there would be no way to pass the right logger into a `func TestFoo(t *testing.T)`. How are other projects dealing with this? Is "normal" log output ignored and only log output from test code that gets the t parameter is used? Thanks, Patrick -- You received this message because you are subscribed to the Google Groups "golang-nuts" group. To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/94d47fc2-6ee2-4c7f-9a21-26ff65acda30n%40googlegroups.com.
[go-nuts] "go test": common prefix for errors
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
--
You received this message because you are subscribed to the Google Groups
"golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to golang-nuts+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/golang-nuts/0d5780d2-f1ec-448d-b3d9-7ed05ee9d5adn%40googlegroups.com.
Re: [go-nuts] "go test": common prefix for errors
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
--
You received this message because you are subscribed to the Google Groups
"golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to golang-nuts+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/golang-nuts/bd27010a-7f48-4e21-9fc5-c8ca2666d03en%40googlegroups.com.
$ cat test/test_test.go
package test
import "testing"
func TestLog(t *testing.T) {
t.Log("Hello world!")
t.Error("Huh, what's this?")
}
$ go test ./test
--- FAIL: TestLog (0.00s)
test_test.go:6: Hello world!
test_test.go:7: Huh, what's this?
FAIL
FAILk8s.io/kubernetes/test 0.003s
FAIL
$ go test -json ./test
{"Time":"2023-03-10T08:19:24.595561773+01:00","Action":"run","Package":"k8s.io/kubernetes/test","Test":"TestLog"}
{"Time":"2023-03-10T08:19:24.595722808+01:00","Action":"output","Package":"k8s.io/kubernetes/test","Test":"TestLog","Output":"===
RUN TestLog\n"}
{"Time":"2023-03-10T08:19:24.595743855+01:00","Action":"output","Package":"k8s.io/kubernetes/test","Test":"TestLog","Output":"
test_test.go:6: Hello world!\n"}
{"Time":"2023-03-10T08:19:24.59575475+01:00","Action":"output","Package":"k8s.io/kubernetes/test","Test":"TestLog","Output":"
test_test.go:7: Huh, what's this?\n"}
{"Time":"2023-03-10T08:19:24.595791388+01:00","Action":"output","Package":"k8s.io/kubernetes/test","Test":"TestLog","Output":"---
FAIL: TestLog (0.00s)\n"}
{"Time":"2023-03-10T08:19:24.59580443+01:00","Action":"fail","Package":"k8s.io/kubernetes/test","Test":"TestLog","Elapsed":0}
{"Time":"2023-03-10T08:19:24.595817364+01:00","Action":"output","Package":"k8s.io/kubernetes/test","Output":"FAIL\n"}
{"Time":"2023-03-10T08:19:24.595975533+01:00","Action":"output","Package":"k8s.io/kubernetes/test","Output":"FAIL\tk8s.io/kubernetes/test\t0.003s\n"}
{"Time":"2023-03-10T08:19:24.596021059+01:00","Action":"fail","Package":"k8s.io/kubernetes/test","Elapsed":0.003}
Re: [go-nuts] "go test": common prefix for errors
"-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. Jason E. Aten schrieb am Freitag, 10. März 2023 um 11:28:56 UTC+1: > Perhaps the -v flag to "go test" would be helpful here, as in "go test -v". > > On Friday, March 10, 2023 at 7:27:48 AM UTC Patrick Ohly wrote: > >> 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 >> >> -- You received this message because you are subscribed to the Google Groups "golang-nuts" group. To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/83016c7f-b340-45ea-9ed3-355e90281346n%40googlegroups.com.
Re: [go-nuts] "go test": common prefix for errors
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". Sean Liao schrieb am Freitag, 10. März 2023 um 19:11:02 UTC+1: > 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. > -- You received this message because you are subscribed to the Google Groups "golang-nuts" group. To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/7d2e99d0-7037-4452-9210-0b1242a97a1bn%40googlegroups.com.
Re: [go-nuts] "go test": common prefix for errors
> 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)`. -- You received this message because you are subscribed to the Google Groups "golang-nuts" group. To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/c857b78b-f2bc-47c5-96ed-0cd68693a6cfn%40googlegroups.com.
