testing: stream t.Log output as it happens #24929

brikis98 · 2018-04-18T17:14:49Z

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.

The text was updated successfully, but these errors were encountered:

randall77 · 2018-04-21T17:12:49Z

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.

brikis98 · 2018-04-21T22:56:43Z

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.

agnivade · 2018-04-22T03:37:18Z

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.

rsc · 2018-04-23T20:08:04Z

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

brikis98 · 2018-04-26T01:34:16Z

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.

ianlancetaylor · 2018-04-30T20:25:31Z

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.

rsc · 2018-05-07T20:28:17Z

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.

jeanbza · 2018-06-04T19:02:22Z

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

Stream output of t.Log in tests via fmt.Printf if -test.v is set Fixes golang#24929

gopherbot · 2018-07-08T09:56:18Z

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

gopherbot · 2018-08-01T01:16:43Z

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

AkihiroSuda · 2018-10-29T05:46:08Z

What's current status?

jeanbza · 2018-10-29T17:56:59Z

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.

ianlancetaylor · 2018-10-29T18:22:33Z

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

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

jeanbza · 2018-11-01T19:46:21Z

Done - will continue conv in gerrit.

cybrcodr · 2019-11-26T18:51:10Z

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)

??

ianlancetaylor · 2019-11-26T21:07:31Z

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.

cybrcodr · 2019-11-26T22:21:39Z

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.

gopherbot · 2020-02-15T04:38:21Z

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

We now only accumulate logs when not using -v. Just drop the sentence entirely rather than try to describe the current situation. Updates #24929 Updates #37203 Change-Id: Ie3bf37894ab68b5b129eff54637893c7a129da03 Reviewed-on: https://go-review.googlesource.com/c/go/+/219540 Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

gopherbot · 2020-03-31T23:14:38Z

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

ianlancetaylor · 2020-04-17T01:34:36Z

See #38458, which suggests changing the format again.

gopherbot · 2020-05-04T20:11:08Z

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

gopherbot · 2020-05-04T20:12:13Z

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

In #24929, we decided to stream chatty test output. It looks like, foo_test.go:138: TestFoo/sub-1: hello from subtest 1 foo_test.go:138: TestFoo/sub-2: hello from subtest 2 In this CL, we refactor the output to be grouped by === CONT lines, preserving the old test-file-before-log-line behavior: === CONT TestFoo/sub-1 foo_test.go:138 hello from subtest 1 === CONT TestFoo/sub-2 foo_test.go:138 hello from subtest 2 This should remove a layer of verbosity from tests, and make it easier to group together related lines. It also returns to a more familiar format (the pre-streaming format), whilst still preserving the streaming feature. Fixes #38458 Change-Id: Iaef94c580d69cdd541b2ef055aa004f50d72d078 Reviewed-on: https://go-review.googlesource.com/c/go/+/229085 Run-TryBot: Emmanuel Odeke <emm.odeke@gmail.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Bryan C. Mills <bcmills@google.com> Reviewed-by: Andrew Bonventre <andybons@golang.org>

gopherbot · 2020-07-09T16:14:09Z

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

Updates #37419. Updates #38458. Updates #24929. Change-Id: I793bb20fa9db4432fc3a5b69956b7108e4695081 Reviewed-on: https://go-review.googlesource.com/c/go/+/241660 Run-TryBot: Jean de Klerk <deklerk@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Dmitri Shuralyov <dmitshur@golang.org>

gopherbot · 2020-07-10T23:30:45Z

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

In #24929, we decided to stream chatty test output. It looks like, foo_test.go:138: TestFoo/sub-1: hello from subtest 1 foo_test.go:138: TestFoo/sub-2: hello from subtest 2 In this CL, we refactor the output to be grouped by === CONT lines, preserving the old test-file-before-log-line behavior: === CONT TestFoo/sub-1 foo_test.go:138 hello from subtest 1 === CONT TestFoo/sub-2 foo_test.go:138 hello from subtest 2 This should remove a layer of verbosity from tests, and make it easier to group together related lines. It also returns to a more familiar format (the pre-streaming format), whilst still preserving the streaming feature. Updates #38458. Fixes #39308. Change-Id: Iaef94c580d69cdd541b2ef055aa004f50d72d078 Reviewed-on: https://go-review.googlesource.com/c/go/+/229085 Run-TryBot: Emmanuel Odeke <emm.odeke@gmail.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Bryan C. Mills <bcmills@google.com> Reviewed-by: Andrew Bonventre <andybons@golang.org> Reviewed-on: https://go-review.googlesource.com/c/go/+/242057 Reviewed-by: Jean de Klerk <deklerk@google.com> Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com> Run-TryBot: Jean de Klerk <deklerk@google.com>

gopherbot added this to the Proposal milestone Apr 18, 2018

gopherbot added the Proposal label Apr 18, 2018

brikis98 mentioned this issue Apr 18, 2018

testing: print log output immediately when it can #23213

Closed

agnivade mentioned this issue Apr 23, 2018

Why can't some of my logs be output in goroutine? #24998

Closed

rsc changed the title ~~Proposal: add support for streaming logs from t.Log as they happen, rather than buffering until the end of the test~~ proposal: log: stream t.Log output as it happens Apr 23, 2018

rsc changed the title ~~proposal: log: stream t.Log output as it happens~~ proposal: testing: stream t.Log output as it happens Apr 23, 2018

matttproud mentioned this issue May 2, 2018

proposal: testing: flush test output on timeout, panic or abort #25213

Closed

rsc changed the title ~~proposal: testing: stream t.Log output as it happens~~ testing: stream t.Log output as it happens May 7, 2018

rsc added the Proposal-Accepted label May 7, 2018

rsc modified the milestones: Proposal, Go1.12 May 7, 2018

bcmills mentioned this issue May 10, 2018

testing: align package duration values #15944

Closed

zegl added a commit to zegl/go that referenced this issue Jul 8, 2018

testing: stream t.Log output as it happens

e2a1dfc

Stream output of t.Log in tests via fmt.Printf if -test.v is set Fixes golang#24929

zegl mentioned this issue Jul 8, 2018

testing: stream t.Log output as it happens #26270

Closed

Groxx mentioned this issue Sep 6, 2018

enforce WorkflowExecutionTimeout in test framework cadence-workflow/cadence-go-client#562

Closed

ianlancetaylor mentioned this issue Sep 24, 2018

testing: testing a list of packages blocks the real-time output #27826

Open

wallrj mentioned this issue Oct 18, 2019

Create E2E test suite improbable-eng/etcd-cluster-operator#26

Merged

gopherbot closed this as completed in a813d3c Oct 22, 2019

kishansagathiya mentioned this issue Nov 1, 2019

Enable P2P Circuit relay and QUIC ipfs-cluster/ipfs-cluster#932

Merged

kylegc mentioned this issue Nov 19, 2019

Logging rework part 2: use t.log in tests appsody/appsody#657

Merged

dmitshur mentioned this issue Feb 13, 2020

testing: parallel subtest log output not properly constrained in go1.14rc1 #37203

Closed

sthagen mentioned this issue Feb 16, 2020

testing: remove obsolete comment in testing.(*T) docs sthagen/golang-go#153

Merged

mengzhuo mentioned this issue Mar 4, 2020

testing: benchmark verbose output changed in 1.14 #37643

Closed

bcmills mentioned this issue Mar 4, 2020

cmd/go: tests that panic or exit are marked as passing when -json flag is used #37555

Closed

mdwhatcott mentioned this issue Mar 24, 2020

cmd/test2json: streamed log output not correctly associated with parallel tests #38050

Closed

mdwhatcott mentioned this issue Mar 31, 2020

test2json: associate streaming log output with the originating test #38189

Closed

ianlancetaylor mentioned this issue Apr 17, 2020

testing: streaming output loses parallel subtest associations #38458

Closed

bcmills mentioned this issue Nov 16, 2020

testing: summary and test output interleaved #40771

Closed

mvdan mentioned this issue Jun 29, 2021

cmd/go: go test -v does not stream logs when testing multiple packages #46959

Open

firelizzard18 mentioned this issue Jul 9, 2021

proposal: go/test: add a package to facilitate test tooling #47101

Closed

golang locked and limited conversation to collaborators Jul 10, 2021

gopherbot added the FrozenDueToAge label Jul 10, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

testing: stream t.Log output as it happens #24929

testing: stream t.Log output as it happens #24929

brikis98 commented Apr 18, 2018 •

edited

Loading

randall77 commented Apr 21, 2018

brikis98 commented Apr 21, 2018

agnivade commented Apr 22, 2018

rsc commented Apr 23, 2018

brikis98 commented Apr 26, 2018 •

edited

Loading

ianlancetaylor commented Apr 30, 2018

rsc commented May 7, 2018

jeanbza commented Jun 4, 2018

gopherbot commented Jul 8, 2018

gopherbot commented Aug 1, 2018

AkihiroSuda commented Oct 29, 2018

jeanbza commented Oct 29, 2018 •

edited

Loading

ianlancetaylor commented Oct 29, 2018

jeanbza commented Nov 1, 2018 •

edited

Loading

cybrcodr commented Nov 26, 2019

ianlancetaylor commented Nov 26, 2019

cybrcodr commented Nov 26, 2019

gopherbot commented Feb 15, 2020

gopherbot commented Mar 31, 2020

ianlancetaylor commented Apr 17, 2020

gopherbot commented May 4, 2020

gopherbot commented May 4, 2020

gopherbot commented Jul 9, 2020

gopherbot commented Jul 10, 2020

testing: stream t.Log output as it happens #24929

testing: stream t.Log output as it happens #24929

Comments

brikis98 commented Apr 18, 2018 • edited Loading

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

Does this issue reproduce with the latest release?

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

Motivation

Current workarounds

Possible solutions

randall77 commented Apr 21, 2018

brikis98 commented Apr 21, 2018

agnivade commented Apr 22, 2018

rsc commented Apr 23, 2018

brikis98 commented Apr 26, 2018 • edited Loading

ianlancetaylor commented Apr 30, 2018

rsc commented May 7, 2018

jeanbza commented Jun 4, 2018

gopherbot commented Jul 8, 2018

gopherbot commented Aug 1, 2018

AkihiroSuda commented Oct 29, 2018

jeanbza commented Oct 29, 2018 • edited Loading

ianlancetaylor commented Oct 29, 2018

jeanbza commented Nov 1, 2018 • edited Loading

cybrcodr commented Nov 26, 2019

ianlancetaylor commented Nov 26, 2019

cybrcodr commented Nov 26, 2019

gopherbot commented Feb 15, 2020

gopherbot commented Mar 31, 2020

ianlancetaylor commented Apr 17, 2020

gopherbot commented May 4, 2020

gopherbot commented May 4, 2020

gopherbot commented Jul 9, 2020

gopherbot commented Jul 10, 2020

brikis98 commented Apr 18, 2018 •

edited

Loading

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

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

brikis98 commented Apr 26, 2018 •

edited

Loading

jeanbza commented Oct 29, 2018 •

edited

Loading

jeanbza commented Nov 1, 2018 •

edited

Loading