testing: stream t.Log output as it happens

Question

testing: stream t.Log output as it happens

brikis98 opened this issue 6 years ago · 32 comments

brikis98 commented 6 years ago

As suggested in #23213 (comment), I'm filing a new issue with a proposal for how to improve t.Log and t.Logf.

What version of Go are you using (`go version`)?

go version go1.9.2

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (`go env`)?

I'm on Darwin, amd64, but this affects all systems/architectures.

Motivation

Consider the following (silly) automated tests:

func TestFoo(t *testing.T) {
	t.Parallel()

	for i := 0; i < 15; i++ {
		t.Logf("%d", i)
		time.Sleep(3 * time.Second)
	}
}

func TestBar(t *testing.T) {
	t.Parallel()

	for i := 0; i < 15; i++ {
		t.Logf("%d", i)
		time.Sleep(2 * time.Second)
	}
}

func TestBaz(t *testing.T) {
	t.Parallel()

	for i := 0; i < 15; i++ {
		t.Logf("%d", i)
		time.Sleep(1 * time.Second)
	}
}

If I run go test -v, I get no log output until all of TestFoo is done, then no output until all of TestBar is done, and again no more output until all of TestBaz is done. This is fine if the tests are working, but if there is some sort of bug, there are a few cases where buffering log output is problematic:

When iterating locally, I want to be able to make a change, run my tests, see what's happening in the logs immediately to understand what's going on, hit CTRL+C to shut the test down early if necessary, make another change, re-run the tests, and so on. If TestFoo is slow (e.g., it's an integration test), I get no log output until the very end of the test. This significantly slows down iteration.
If TestFoo has a bug that causes it to hang and never complete, I'd get no log output whatsoever. In these cases, t.Log and t.Logf are of no use at all. This makes debugging very difficult.
Moreover, not only do I get no log output, but if the test hangs too long, either the Go test timeout kills the test after 10 minutes, or if I increase that timeout, many CI servers will also kill off tests if there is no log output after a certain amount of time (e.g., 10 minutes in CircleCI). So now my tests are killed and I have nothing in the logs to tell me what happened.

Current workarounds

The main workaround is to replace all t.Logf calls with either fmt.Printf or a custom logger. Since we often want to iterate quickly on tests, and since debugging is such an important use case, in practice, that means we never use t.Logf at all.

This seems like a missed opportunity. Go has a lot of powerful testing tools built in, and we usually pass the t variable around to many test methods so they can call t.Fatal(), t.Name(), etc. It would be great if t had a logger built in that we could actually use. Honestly, the only thing it's really missing is some way to configure the logger to write to stdout immediately, rather than buffering.

Possible solutions

Probably the easiest way to improve t.Log and t.Logf is to add a -test.streamlogs option to the go test command. When this option is set, t.Log and t.Logf write to stdout immediately, instead of buffering.

This means the output format with this option set wouldn't be backwards compatible, but the expectation is that this option would only be used for local debugging, and not something used in your CI system.

Answer 1 · 2018-04-21T17:12:49.000Z

I think we can modify -v to get what you want. For instance:

--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -560,6 +560,10 @@ func (c *common) FailNow() {
 func (c *common) log(s string) {
        c.mu.Lock()
        defer c.mu.Unlock()
+       if c.chatty {
+               fmt.Printf("%s: %s", c.name, c.decorate(s))
+               return
+       }
        c.output = append(c.output, c.decorate(s)...)
 }

This will print output immediately, and you get something like this:

$ go test -v
=== RUN   TestFoo
=== PAUSE TestFoo
=== RUN   TestBar
=== PAUSE TestBar
=== RUN   TestBaz
=== PAUSE TestBaz
=== CONT  TestFoo
TestFoo: 	test_test.go:12: 0
=== CONT  TestBaz
TestBaz: 	test_test.go:30: 0
=== CONT  TestBar
TestBar: 	test_test.go:21: 0
TestBaz: 	test_test.go:30: 1
TestBar: 	test_test.go:21: 1
TestBaz: 	test_test.go:30: 2
TestFoo: 	test_test.go:12: 1
TestBaz: 	test_test.go:30: 3
TestBar: 	test_test.go:21: 2
TestBaz: 	test_test.go:30: 4
TestBaz: 	test_test.go:30: 5
TestBar: 	test_test.go:21: 3
TestFoo: 	test_test.go:12: 2
TestBaz: 	test_test.go:30: 6
TestBaz: 	test_test.go:30: 7
TestBar: 	test_test.go:21: 4
TestBaz: 	test_test.go:30: 8
TestFoo: 	test_test.go:12: 3
TestBaz: 	test_test.go:30: 9
TestBar: 	test_test.go:21: 5
TestBaz: 	test_test.go:30: 10
TestBaz: 	test_test.go:30: 11
TestBar: 	test_test.go:21: 6
TestFoo: 	test_test.go:12: 4
TestBaz: 	test_test.go:30: 12
TestBaz: 	test_test.go:30: 13
TestBar: 	test_test.go:21: 7
TestBaz: 	test_test.go:30: 14
TestFoo: 	test_test.go:12: 5
--- PASS: TestBaz (15.01s)
TestBar: 	test_test.go:21: 8
TestBar: 	test_test.go:21: 9
TestFoo: 	test_test.go:12: 6
TestBar: 	test_test.go:21: 10
TestFoo: 	test_test.go:12: 7
TestBar: 	test_test.go:21: 11
TestFoo: 	test_test.go:12: 8
TestBar: 	test_test.go:21: 12
TestBar: 	test_test.go:21: 13
TestFoo: 	test_test.go:12: 9
TestBar: 	test_test.go:21: 14
TestFoo: 	test_test.go:12: 10
--- PASS: TestBar (30.01s)
TestFoo: 	test_test.go:12: 11
TestFoo: 	test_test.go:12: 12
TestFoo: 	test_test.go:12: 13
TestFoo: 	test_test.go:12: 14
--- PASS: TestFoo (45.02s)
PASS
ok  	_/Users/khr/gowork/issue24929	45.019s

It's pretty jumbled, but gets you what you want.
I don't think there's any issue with changing the format of -v output.

Answer 2 · 2018-04-21T22:56:43.000Z

That would be great 👍

I agree the output is jumbled, but it's actually surprisingly easy to follow so long as each line is prefixed with the test name, and if it's very grep-friendly to make things even easier to read.

Answer 3 · 2018-04-22T03:37:18.000Z

Yea, this is totally OK. Usually, I run that single test when debugging a test. So I don't need to bother about other outputs getting jumbled. I just want the log output to appear immediately.

Answer 4 · 2018-04-23T20:08:04.000Z

I'm skeptical that we can modify -v output, for what little that's worth.

Answer 5 · 2018-04-26T01:34:16.000Z

One more note on the topic of log streaming. It seems that if you run go test against multiple packages (e.g., go test -v ./...), the log output is buffered, and using fmt.Println or any other utility that writes to stdout does not help in this instance. I'm not sure on the buffering logic, but it seems like no log output shows up until all the tests in an entire package are done, and the log output is displayed one package at a time.

This leads to all the same issues mentioned above, and is especially problematic if you have a single slow package (e.g., one with integration tests), as many CI systems will kill your tests after a certain timeout with no log output (e.g., 10 min in CircleCI). Changing your code doesn't help in this case. The only workaround I've found is to set -p 1, so each package is tested sequentially. This seems to allow fmt.Println to stream to stdout as normal, but significantly reduces the parallelism you can get in your tests.

Answer 6 · 2018-04-30T20:25:31.000Z

We could argue that the output of -test.v is intended for human consumption, and as such is OK to change along the lines that @randall77 suggests above. Programs that want to parse test output should use -test.json. Of course, this means that we might need to modify the -test.json output in some way so that the test2json program can parse the new output.

Answer 7 · 2018-05-07T20:28:17.000Z

The redefinition of -v is a bit concerning to me but maybe not enough to sink the idea.
Let's land this early in the Go 1.12 cycle, along with changes to test2json to parse the new prefixes.
If it turns out to be bad, we'll have time to roll it back.

Answer 8 · 2018-06-04T19:02:22.000Z

Is anyone working on an impl? If not, I'll try something this weekend.

Answer 9 · 2018-07-08T09:56:18.000Z

Change https://golang.org/cl/122581 mentions this issue: testing: stream t.Log output as it happens

Answer 10 · 2018-08-01T01:16:43.000Z

Change https://golang.org/cl/127120 mentions this issue: testing: -v flag streams logs

Answer 11 · 2018-10-29T05:46:08.000Z

What's current status?

Answer 12 · 2018-10-29T17:56:59.000Z

Still waiting on for it to be able to make it into Go1.12, I think. @ianlancetaylor is that still some time off? Sorry, I'm not super aware of the timeline.

Also I need to rebase, but I'll hold off until it's feasible for it to make it in.

Answer 13 · 2018-10-29T18:22:33.000Z

Timeline is at https://golang.org/wiki/Go-Release-Cycle .

The changes now have merge conflicts. Can you resolve those? Thanks.

Answer 14 · 2018-11-01T19:46:21.000Z

Done - will continue conv in gerrit.

Answer 15 · 2018-11-05T08:44:14.000Z

Will this affect just go test -v, or also go test -v ./...? I would expect that only the former would be changed. I don't see a benefit to changing the case where multiple packages are tested.

Answer 16 · 2018-11-05T15:46:25.000Z

@mvdan Replied to your question in gerrit. (tldr: my change as it stands changes it slightly)

Answer 17 · 2018-11-05T19:25:21.000Z

Lately I've been doing something interesting with t.Log that this change would make less useful.

For code that accepts and uses some sort of logger I wire the logger up to t.Log so that all log output from the code is collected by the testing framework. When using this technique go test stays nicely quiet when the tests pass, but includes the log output when a test fails and that log output is properly grouped with each test. It also means that go test -v has the logs from each test nicely segregated. This is especially nice when many of the tests include calls to t.Parallel which I try to use as much as possible. I think it would be a shame to lose this property.

I agree with @ianlancetaylor that the output of -test.v is for human consumption, but as a human I find it far easier to consume the output when it is segregated by test case.

I understand the value of the original feature request, but I don't think it is an obviously better implementation of t.Log for all use cases or even a majority. I suggest go test -v should keep it's current behavior and if the streaming behavior is added that it is opt-in.

Answer 18 · 2018-11-06T15:59:29.000Z

So I've run into a bit of an unspecified area implementing this. When go test -bench=. -v is used, what should the behavior be?

Currently, -bench causes the cursor to hang on the current line until the results are in, then prints the results, then prints the logs. E.x.:

# after .1s
$ go test -bench=. -v
BenchmarkFib10-8

# after 1s the results are printed on the _same_ line, then the log output on the next few lines
$ go test -bench=. -v
BenchmarkFib10-8   	      10	 103238326 ns/op
--- BENCH: BenchmarkFib10-8
    foo_test.go:53: logging bench...
    foo_test.go:53: logging bench...
    foo_test.go:53: logging bench...
	... [output truncated]
PASS

However, with a very naive implementation, if we log immediately upon log receipt we'd get,

# after 1s
$ go test -bench=. -v
BenchmarkFib10-8
    foo_test.go:53: BenchmarkFib10: logging bench...
    foo_test.go:53: BenchmarkFib10: logging bench...
    foo_test.go:53: BenchmarkFib10: logging bench...
      10	 103553535 ns/op
PASS

What should this look like instead? Should the bench behavior be unchanged?

Answer 19 · 2019-01-17T15:16:00.000Z

Did this happen for 1.12? (Should it be closed, or re-milestoned?)

Answer 20 · 2019-01-21T21:14:00.000Z

@bcmills This hasn't happened yet. There's an outstanding question about what to do in benchmarking mode. My intuition is telling me to just revert to normal behavior when using -bench (don't stream), but my team is a bit understaffed at the moment so I've not found the time to circle back. Sorry!!

Answer 21 · 2019-04-15T22:48:22.000Z

For posterity: the latest patch introduces streaming to benchmarking, too. It prints the name of the benchmark, then streaming happens, then prints the name again + results at the end.

Answer 22 · 2019-06-09T23:29:33.000Z

Sorry @jadekler that we didn't get back to this during the early Go1.13 cycle and since we are currently in a Go1.13 freeze so am not sure if the experimental nature of it will fly for it to still be included in Go1.13, even though the CL was made earlier.

Answer 23 · 2019-11-26T18:51:10.000Z

We have a wrapper code that parses the output, and I had to rework that in order to account for this change.

I do have a concern with the legibility of the output especially when running multiple tests and subtests. Here's a simple example --

=== RUN   TestNestedSubtestFails
    TestNestedSubtestFails: multilevelsubtest_test.go:11: TestNestedSubtestFails -- level 1
         new line here
=== RUN   TestNestedSubtestFails/subtest1
    TestNestedSubtestFails/subtest1: multilevelsubtest_test.go:13: subtest1 -- level 2
=== RUN   TestNestedSubtestFails/subtest1/subtest1-1
    TestNestedSubtestFails/subtest1/subtest1-1: multilevelsubtest_test.go:15: subtest1-1 -- level 3
=== RUN   TestNestedSubtestFails/subtest1/subtest1-1/subtest1-1-1
    TestNestedSubtestFails/subtest1/subtest1-1/subtest1-1-1: multilevelsubtest_test.go:17: failed
=== RUN   TestNestedSubtestFails/subtest1/subtest1-2
=== RUN   TestNestedSubtestFails/subtest1/subtest1-2/subtest1-2-1
=== RUN   TestNestedSubtestFails/subtest1/subtest1-2/subtest1-2-2
=== RUN   TestNestedSubtestFails/subtest2
    TestNestedSubtestFails/subtest2: multilevelsubtest_test.go:26: subtest2 -- level 2
    TestNestedSubtestFails/subtest2: multilevelsubtest_test.go:27: I have a nephew/niece node!
--- FAIL: TestNestedSubtestFails (0.00s)
    --- FAIL: TestNestedSubtestFails/subtest1 (0.00s)
        --- FAIL: TestNestedSubtestFails/subtest1/subtest1-1 (0.00s)
            --- FAIL: TestNestedSubtestFails/subtest1/subtest1-1/subtest1-1-1 (0.00s)
        --- PASS: TestNestedSubtestFails/subtest1/subtest1-2 (0.00s)
            --- PASS: TestNestedSubtestFails/subtest1/subtest1-2/subtest1-2-1 (0.00s)
            --- PASS: TestNestedSubtestFails/subtest1/subtest1-2/subtest1-2-2 (0.00s)
    --- PASS: TestNestedSubtestFails/subtest2 (0.00s)
FAIL

Imagine if there are more tests/subtests that are running in parallel. I understand the original request, but I wish that was done as an optional flag instead of being the default with no way to opt out.

Anyways, I'd like to know though if given the current implementation, is it possible for log lines to show up in between result lines, e.g.

--- FAIL: TestNestedSubtestFails (0.00s)
    TestFoo: foo_test.go:11: log line from foo
    --- FAIL: TestNestedSubtestFails/subtest1 (0.00s)
        --- FAIL: TestNestedSubtestFails/subtest1/subtest1-1 (0.00s)
            --- FAIL: TestNestedSubtestFails/subtest1/subtest1-1/subtest1-1-1 (0.00s)
        --- PASS: TestNestedSubtestFails/subtest1/subtest1-2 (0.00s)
            --- PASS: TestNestedSubtestFails/subtest1/subtest1-2/subtest1-2-1 (0.00s)
    TestFoo: foo_test:go:20: another log line from foo
            --- PASS: TestNestedSubtestFails/subtest1/subtest1-2/subtest1-2-2 (0.00s)
    --- PASS: TestNestedSubtestFails/subtest2 (0.00s)

??

Answer 24 · 2019-11-26T21:07:31.000Z

Using an optional flag would just be another knob, and it shouldn't be necessary. People who want something like the old output should be able to run the current output through sed. (I'm not saying the current output is clearly better, I'm just saying that I don't think another knob is the right approach.)

I don't think the testing package will ever display t.Log output between result lines, but I believe that it can display data written to standard output between result lines.

Answer 25 · 2019-11-26T22:21:39.000Z

Thanks for the response.

It won't be a simple sed to do exact match for all cases:)

Having standard out between result lines can mess up parsing if the output produces fake result lines. Anyways, it's probably not likely.

Answer 26 · 2020-02-15T04:38:21.000Z

Change https://golang.org/cl/219540 mentions this issue: testing: remove obsolete comment in testing.(*T) docs

Answer 27 · 2020-03-31T23:14:38.000Z

Change https://golang.org/cl/226757 mentions this issue: test2json: associate streaming log output with the originating test

Answer 28 · 2020-04-17T01:34:36.000Z

See #38458, which suggests changing the format again.

Answer 29 · 2020-05-04T20:11:08.000Z

Change https://golang.org/cl/232157 mentions this issue: testing: reformat test chatty output

Answer 30 · 2020-05-04T20:12:13.000Z

Change https://golang.org/cl/229085 mentions this issue: testing: reformat test chatty output

Answer 31 · 2020-07-09T16:14:09.000Z

Change https://golang.org/cl/241660 mentions this issue: doc/go1.15: add line for testing streaming change

Answer 32 · 2020-07-10T23:30:45.000Z

Change https://golang.org/cl/242057 mentions this issue: [release-branch.go1.14] testing: reformat test chatty output

What version of Go are you using (go version)?