testing: print log output immediately when it can

[rogpeppe]

Diagnosing a test that hangs up is made harder because it's
T.Logf doesn't print any output until the test completes (which might
never happen).

Before a test has called t.Parallel, it would be nice if it could print
any log output immediately.

This would also make it easier to see test Logf output in sequential context with
print statements made by the code being called by the test.

This issue is made worse when logging infrastructure is hooked up
to T.Log so that it doesn't pollute normal test output by printing to
stdout.

[cznic]

But only with -v.

[rogpeppe]

@cznic Absolutely - I'm not proposing any change in whether the log output is shown, just when it appears.

[ALTree]

As noted in #23567 (a duplicate of this), the issue also affects Errorf calls (since Errorf calls Logf).

[nerdralph]

This is also a problem if the test crashes. I noticed this when testing go code with a buggy OpenCL driver. Having the log output flush after each call would make it much easier to find the exact point in the test that failed.

[mvdan]

Sounds like there is no investigation required here - the proposed change is clear. Labelling as NeedsDecision.

/cc @mpvl

[jeanbza]

I'll add my 2c here quickly:

The fact that -v does not show logs means I get no sense of timing in failed test runs. Nor do I see failed tests, as @nerdralph mentioned.

It's a real bummer to mass replace t.Log with fmt.Println, get my tests fixed, and then mass replace fmt.Println with t.Log.

[agnivade]

@ianlancetaylor - Can we get this in for 1.11 ? What are the factors that are yet to be "decided" (because of the needsdecision label) ?

I have got bitten by this several times and would be great not to resort to printing through fmt package.

Also curious regarding why it was initially designed not to print any output until the test has finished. Printing output immediately after a call to t.Log is what most people would think will happen. This is just a very weird counter-intuitive behavior.

[rsc]

The current output is:

r$ go test -run Reader
--- FAIL: TestReader (0.00s)
	reader_test.go:18: bye
FAIL
exit status 1
FAIL	strings	0.105s
r$ 

We can't start printing log output without knowing whether to start with PASS or FAIL. Various things read this output, we can't just reorder it.

[agnivade]

Ah, got it.

[rogpeppe]

We can't start printing log output without knowing whether to start with PASS or FAIL. Various things read this output, we can't just reorder it.

Ah, I'd missed that detail.

Would it be possible to to add some kind of a flag to enable this somehow, even if it involves changing the output syntax in that case? Something like -force-immediate-output. The fact that it is not possible to produce output immediately has made diagnosis of deadlocks and unexpected crashes in tests much harder for me in the past, and I'd prefer a solution that didn't involve temporary hacks to the stdlib.

[brikis98]

@rsc What about adding a --stream-logs or similar flag that streams log entries to stdout as they happen (rather than at the end) and then also prints all the logging info in the usual format after the --- FAIL or --- SUCCESS, as usual?

The lack of log output for long-running tests is a big problem, as it makes it harder to debug (especially when things go wrong, such as a test hanging or when you have race conditions), and some CI systems, such as CircleCI, terminate the tests if there has been no log output for too long (e.g., 10 min). I understand the need for backwards compatibility in the test logs, but I'm sure we can figure out a solution that solves both problems, rather than just closing the issue, and telling everyone to do a massive search & replace every time they want to debug...

[ianlancetaylor]

I believe that if you cd to the directory and run go test with no arguments the output will stream to the terminal.

[brikis98]

Hm, that's not what I'm seeing:

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

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

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

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

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

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

If I create a file with the 3 tests above and 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. If, for example, TestFoo took more than 10 minutes, CircleCI would fail the build due to lack of output. If TestFoo had a bug and was hanging, even when running locally, I'd get no output whatsoever, which makes debugging hard. Being forced to replace all t.Logf calls with fmt.Printf or similar just to preserve log text formatting seems like a very poor trade off.

[ianlancetaylor]

Oh, I forgot to say: use fmt.Printf, not t.Log.

[jeanbza]

That works for me, but as I mentioned in #24262 it's a real bummer that the workflow is "grep and replace t.Log with fmt.Printf, debug, grep and replace fmt.Printf with t.Log".

[brikis98]

@ianlancetaylor Right, but the central question in this issue is having t.Logf do that for you. If I need to switch all my logging to fmt.Printf to do debugging, why does t.Logf even exist?

[ianlancetaylor]

The testing package framework is fundamentally poorly designed for long running tests that need to report progress as they go. I'm suggesting a workaround.

t.Logf has a different purpose: it logs potentially interesting data as the test runs, but the data is only reported to the user if the test fails, in the hopes that it will explain the failure. (You can use the -test.v option to see the t.Logf output either way, but that is not the normal case.)

[brikis98]

The testing package framework is fundamentally poorly designed for long running tests that need to report progress as they go. I'm suggesting a workaround.

I appreciate the help. FWIW, we are using the workaround, which involves creating a custom logger and passing it all throughout the test code, but that's clunky. My hope is to discuss whether something can be done to make Go a better fit for this sort of testing. Happy to open a new issue if that's more appropriate!

t.Logf has a different purpose: it logs potentially interesting data as the test runs, but the data is only reported to the user if the test fails, in the hopes that it will explain the failure. (You can use the -test.v option to see the t.Logf output either way, but that is not the normal case.)

I guess the key questions are (a) why is that the purpose of t.Log and (b) why not expand the purpose? Note the following:

• Having to log things at test time is a very common use case.
• Running tests interactively on your local computer and reading the output is also a very common use case. In fact, that's arguably the "normal" way of developing tests.
• Long running tests (where long means more than ~10 min) are not exactly unheard of either. Most "integration tests" take this long. But note that the lack of "immediate" logging affects shorter tests too, as the real desire is to see log output as it happens rather than at the end of the test.

It's awesome that Go has a lot of powerful testing tools built in. We tend to pass the t variable around to many test utilities already so we can call t.Fatal(...), t.Name(), etc. Being able to log the same way makes a lot of sense. All that's missing is some way to see those logs "streaming" when an extra flag is set, specifically to make a VERY common task—debugging—a lot easier.

[zombiezen]

So if t.Log's purpose is (and I agree with this):

it logs potentially interesting data as the test runs, but the data is only reported to the user if the test fails, in the hopes that it will explain the failure.

I find that t.Log does not fulfill that purpose in an important test failure mode: the test hanging or panicking. Right now, if you have a test that hangs (infinite loop, deadlock, etc.) and the test times out or otherwise panics, I can't see the log. (Of course, the s/t.Logf/fmt.Printf/ workaround helps here, but it is that: a workaround.)

[ianlancetaylor]

Sure, we can discuss other approaches. I've seen one suggestion so far: add a -test.streamlogs option that causes output to be produced immediately and also later. That seems like an unfortunate duplication. I'm also not clear on how it would interact with the -test.json option. In any case, that idea should probably be made as a separate proposal.

[randall77]

Why do we not get t.Logf output when panicking, or when a timeout triggers a failure? That just seems like a bug.

[brikis98]

In any case, that idea should probably be made as a separate proposal.

What's the best way to do that? File a new bug in this repo?

[ianlancetaylor]

Yes. https://github.com/golang/proposal/blob/master/README.md

[brikis98]

I just filed #24929 as a proposal for adding a -test.streamlogs flag.

[wlcy]

what if in a test we call another func that use fmt.XXX to output the progress info if test can't flush out the output immediately?