Test output does not stream

[peterbourgon]

• go version go1.14.4 darwin/amd64
• Visual Studio Code 1.46.1 (cd9ea6488829f560dc949a8b2fb789f3cdc05f5d, 2020-06-17T21:17:14.222Z)
• Go extension version 0.15.1
• go env
• settings.json

Ensure you're using Go 1.14. Write a test like this one.

func TestBug(t *testing.T) {
	for i := 0; i < 5; i++ {
		t.Log(i)
		time.Sleep(100 * time.Millisecond)
	}
}

Invoke the test through the plugin via e.g. Cmd+Shift+P > Go: Test Function At Cursor.

Expected behavior: the numbers 0 through 5 are streamed in real time to the output tab.

Actual behavior: the output tab is activated but blank until the test completes, at which point the complete test output is printed to the tab.

[rubxcubedude]

i'm seeing this as well: I'll note that this method broke for me ~ 2 months ago and had worked from Nov 2018 till then even with versions of go < 1.14

[hyangah]

@peterbourgon do you mean when -v option is given?

It seems like vscode buffers the output until the test's result becomes available and handles differently based on whether the test passes or not.

https://github.com/golang/vscode-go/blob/master/src/testUtils.ts#L339-L353

I guess this needs to be changed.

[hyangah]

I guess the intention of such buffering was to extract the package path included in the test's FAIL or ok message. Then, it uses the package path to rewrite the file name in the test error messages. If vscode can recognize and offer a convenient way to go to the file, that will be awesome.

It looks like, though, that's broken. If we can expand the file path reliably, it would be nice. But the test output doesn't include the package path until the test result becomes available. :-(

Are we ok not trying to infer the full path of the error message location?

[peterbourgon]

do you mean when -v option is given?

Ah, yes, sorry, I should have made that more explicit, indeed I'm using "go.testFlags": ["-v"]. Although I find it interesting that, without this flag, the plugin will suppress all output, not only t.Log statements (obviously) but any fmt.Printfs in the actual code under test. That also seems like a bug?

[hyangah]

@peterbourgon

without this flag, the plugin will suppress all output, not only t.Log statements (obviously) but any fmt.Printfs in the actual code under test. That also seems like a bug?

Yes, the current code buffers everything from stdout/stderr until it finds the test result and its package path. go test output is all in stdout, so the extension has no way to distinguish it's from fmt.Printf or t.Logf. :-(

For a single test case, we may be able to make the extension to get the information about the file path from other sources and don't need to wait for the test results. But when multiple tests run (e.g. go test ./...), unfortunately, the test output is not very stream-processing friendly, and we can't not easily tell which package test output messages until the test ends. :-(
I will file a feature request to improve the test output format.

 ~/hello$ go test ./... 
--- FAIL: TestBug (0.52s)
    hello_test.go:10: error 0
    hello_test.go:10: error 1
    hello_test.go:10: error 2
    hello_test.go:10: error 3
    hello_test.go:10: error 4
FAIL
FAIL    w       0.532s
--- FAIL: TestBug (0.52s)
    bye_test.go:10: error 0
    bye_test.go:10: error 1
    bye_test.go:10: error 2
    bye_test.go:10: error 3
    bye_test.go:10: error 4
FAIL
FAIL    w/bye   0.532s
FAIL

In the mean, I am afraid we need to decide what to give up: streaming test output vs link to the log location

[peterbourgon]

I'm speaking from total ignorance, but Is it not possible to do the linking on a per-line basis? Or do you need to operate on the complete output?

[hyangah]

@peterbourgon I think vscode output channel parses the text and does the linking if the file name is relative to cwd. For example, if I run the above test from the project root directory (module w), we rewrite hello_test.go:10 to ./hello_test.go:10, and './bye/bye_test.go:10`. Then, the vscode output channel makes it clickable, and when users clicks the link, it will open to the location in the editor.

In order to know the directory of bye_test.go, currently the extension waits until it sees the FAIL w/bye 0.532s line, and then rewrites all the accumulated logs.

Does it make sense?

Of course, this file rewriting logic is currently broken - so I am talking based on my experience with javascript :-P

[gopherbot]

Change https://golang.org/cl/242539 mentions this issue: src/testUtils: fix filename rewrites in modules mode test output

[gopherbot]

Change https://golang.org/cl/242540 mentions this issue: src/testUtils: stream output when testing a single package with -v

[hyangah]

So, in the cl/242540, I disabled the buffering for the test with a single package & -v option.
When testing multiple package (e.g. Go: Test All Packages in Workspaces), we still buffer.

I just realized that we can do better with the -json output but I expect this will be a bigger change. I will take a look later.

[peterbourgon]

@hyangah Nice find!