cmd/test2json: filtering out testing service messages or mark them in a special way

[zolotov]

With -json parameter enabled go test still generates service messages like "===RUN", which don't make much sense in json-mode.

I would be nice to exclude them from the output or at least mark them with an additional attribute, so the client would be able to filter these messages by themselves.

[ianlancetaylor]

CC @rsc

To be clear, the output is all in a JSON format, right? You are talking specifically about lines like

{"Time":"2017-12-15T13:31:22.081441728-08:00","Action":"output","Package":"bytes","Test":"TestEqualNearPageBoundary","Output":"=== RUN   TestEqualNearPageBoundary\n"}

You are suggesting that test2json should omit those lines, or mark them in some way that lets them be distinguished from other Output lines.

Is that right?

[zolotov]

Yes, please consider following test:

package a

import (
	"fmt"
	"testing"
)

func TestFoo(t *testing.T) {
	fmt.Println("=== RUN   TestFoo")
}

Now it will produces following output:

{"Time":"2017-12-16T08:23:08.648686205+10:00","Action":"run","Package":"command-line-arguments","Test":"TestFoo"}
{"Time":"2017-12-16T08:23:08.649143121+10:00","Action":"output","Package":"command-line-arguments","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}
{"Time":"2017-12-16T08:23:08.649168581+10:00","Action":"run","Package":"command-line-arguments","Test":"TestFoo"}
{"Time":"2017-12-16T08:23:08.649179216+10:00","Action":"output","Package":"command-line-arguments","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}

But should produce either this one:

{"Time":"2017-12-16T08:23:08.648686205+10:00","Action":"run","Package":"command-line-arguments","Test":"TestFoo"}
{"Time":"2017-12-16T08:23:08.649143121+10:00","Action":"output","Package":"command-line-arguments","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}

or

{"Time":"2017-12-16T08:23:08.648686205+10:00","Action":"run","Package":"command-line-arguments","Test":"TestFoo"}
{"Time":"2017-12-16T08:23:08.649143121+10:00","Action":"service","Package":"command-line-arguments","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}
{"Time":"2017-12-16T08:23:08.649179216+10:00","Action":"output","Package":"command-line-arguments","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}

[rsc]

The whole design here is that test2json reads the test output (because the test may crash or have prints directly to stdout/stderr and therefore cannot be trusted to print JSON itself). If a test is going out of its way to print invalid framing, then test2json is going to get confused, and I'm sorry but there's very little we can do about it.

I think this is working well enough. Have you ever seen this in practice?

[zolotov]

In my experience, the assumptions like "let's use that string as a marker since nobody will use it in the real programs" fail in few months :(

I think this is working well enough. Have you ever seen this in practice?

Unfortunately, yes, we had several bug reports related to it. This one was easy to find: go-lang-plugin-org/go-lang-idea-plugin#2678

[bradfitz]

Perhaps test2json could make up a random string delimiter (like multipart/mime) and pass it to the child process to use.

[rsc]

OK, but at least that bug is not as trivial as the reproduction you've reported. It is doing ordinary output as part of the test, which will be indented differently and can therefore be distinguished from the usual FAIL lines. In fact, test2json almost handles it correctly:

r$ cat >x.txt
=== RUN   TestActualCase
--- FAIL: TestActualCase (0.00s)
        foo_test.go:14: Differed.
                Expected: MyTest:
                --- FAIL: Test output from other tool
                Actual: not expected
FAIL
exit status 1
FAIL    github.com/org/project/badtest     0.049s
r$ go tool test2json < x.txt
{"Action":"run","Test":"TestActualCase"}
{"Action":"output","Test":"TestActualCase","Output":"=== RUN   TestActualCase\n"}
{"Action":"output","Test":"TestActualCase","Output":"--- FAIL: TestActualCase (0.00s)\n"}
{"Action":"output","Test":"TestActualCase","Output":"        foo_test.go:14: Differed.\n"}
{"Action":"output","Test":"TestActualCase","Output":"                Expected: MyTest:\n"}
{"Action":"output","Test":"TestActualCase","Output":"                Actual: not expected\n"}
{"Action":"fail","Test":"TestActualCase"}
{"Action":"output","Output":"FAIL\n"}
{"Action":"output","Output":"exit status 1\n"}
{"Action":"output","Output":"FAIL    github.com/org/project/badtest     0.049s\n"}
{"Action":"fail"}
r$ 

It has dropped the ---FAIL line entirely, which is wrong, but fixable. I'm happy to fix that.

The mime random string is the obvious answer (or just some flag that turns on a fixed string like "\xff\x00") but I'm not interested in the complexity of adding a new flag until it's clearer that we must.

[gopherbot]

Change https://golang.org/cl/86238 mentions this issue: cmd/test2json: fix test log output containing test output

[zolotov]

OK, but at least that bug is not as trivial as the reproduction you've reported.

Ian asked for an example, so I gave the minimal one.

Despite I brought the bug report, my initial intention (as it's stated in the issue description) is to exclude service-output on the client that doesn't make much sense in -json mode. IDEs and CIs usually can split outputs of tests in separate screens for easier-reading, service messages are more like noise there.

Is there a guarantee that all service output like "===RUN" is going to be printed without indent, and all other output will have non-zero indentation? If so, test2json itself or its clients could filter them out.

[zolotov]

@rsc b32ac54 doesn't fix the initial request. Please consider reopening the issue.

[ianlancetaylor]

Yes, I think your example sidetracked the issue. The real issue is whether the generated JSON should have some easy way to distinguish the framing messages from any other test output. Reopening.

[rsc]

I don't think you should attempt to exclude that output, for a variety of reasons (parallel tests being one). It's certainly not a release blocker at this point.

[rsc]

And to emphasize what I wrote above, I'm not interested in the complexity of adding a new flag until it's clearer that we must. So real examples of how this might innocently occur would be welcome and would help change the priority here. Without real examples I think this is not worth fixing further.

[zolotov]

for a variety of reasons (parallel tests being one)

What's about parallel tests? They usually produce even more service messages. Could you please elaborate the rest reasons?

Not sure what example you expect, but here is my case. Outputs of different tests are split based on JSON. There is no need to show these "===RUN", "=== PAUSE", etc, they only make reading of test's output difficult.

[zolotov]

Offtopic. Speaking of parallel tests. Please look at the screenshot. Is this expected that output of TestParallel1 was marked as an output of TestParallel3?

{"Time":"2018-01-05T11:42:16.101166101+03:00","Action":"output","Package":"command-line-arguments","Test":"TestParallel3","Output":"== Custom Output of TestParallel1\n"}

[rsc]

@zolotov Yes, it is expected. Tests should use t.Log/t.Error and not fmt.Printf. If they insist on using fmt.Printf then we will assign it as best we can, but it can't be perfect. In the case of parallel tests there are multiple tests all running simultaneously. If they print to os.Stdout directly, there's literally no way to tell the output apart. test2json does the best it can, which is to assign the output to the test named in the most recent CONT line.

If tests are running in parallel, then sorry, but they can't print to os.Stdout/os.Stderr directly and expect magic to happen to figure out which test printed what. This is basically the same reason I don't think we need to worry about tests that print raw framing to os.Stdout/os.Stderr. If you write a test that goes out of its way to make the output confusing, well, the output will be confusing.

Note that as of my CL above, test2json now correctly handles framing printed by t.Log/t.Error. And it has always correctly handled parallel test output printed using t.Log/t.Error. The problems only happen when tests make direct prints to os.Stdout/os.Stderr. I don't believe the answer has to be more complexity. The answer is don't do that.

[zolotov]

@rsc I think it's ok to require using t.Log/t.Error in tests, but it might be a production code (that is invoked during testing) that prints directly to os.Stdout/os.Stderr and there is no way to invoke t.Log/t.Error there.

Regarding omitting service-messages, is the example I provided good enough? What about the variety of reasons not to exclude service-messages?

[dnephin]

The real issue is whether the generated JSON should have some easy way to distinguish the framing messages from any other test output.

I've encountered a similar problem so I'll present my use case.

I'm reading the test2json output to:

• count the tests that were run (ex: total number of tests run, number of failed tests, number of skipped tests)
• print all the failure/skip messages at the end of the test run to make them easier to see all together
• customize test output

Generally this is working well, but I have to write some ugly string comparison to identify some of the framing messages.

To reproduce the standard go test output format (which is necessary if I want to gather the stats but still give the user the normal test output) I have standardQuietFormat:

if testEvent.Test == "" && event.Output != "PASS\n" {
    // Print event.Output
}

If this PASS\n message was identified as a framing message it would be a bit cleaner to implement.

Another example is trying to identify if package Output is a framing message, or if it's output from TestMain or a panic in init(), isPkgFailureOutput:

func isPkgFailureOutput(event TestEvent) bool {
	out := event.Output
	return all(
		event.Test == "",
		event.Action == ActionOutput,
		out != "PASS\n",
		out != "FAIL\n",
		!strings.HasPrefix(out, "FAIL\t"+event.Package),
		!strings.HasPrefix(out, "ok  \t"+event.Package),
	)
}

It's necessary to check the output against a bunch of possible lines that are framing messages to determine if the line is test output or a framing message.

A field in TestEvent which marks these lines would be great, and I think it would make the test2json output easier to consume for more use cases.

[rodrigc]

@zolotov I reported a problem over here: gotestyourself/gotestsum#22 (comment) to @dnephin where with go test -json I seem to be getting "Action":"pass" emitted twice for each test in the output JSON.

Am I doing something wrong with how I am generating my test output?

I found this with go 1.10.3

[zolotov]

@robfig I don't know, sorry, I'm a client of test2json just like you :) It's better to ask Ian or Russ about it, I think, or to file a separate issue.

[mfridman]

Not sure I agree with one of the points above.

I would be nice to exclude them from the output

When writing a tool that reads in the output of go test it's possible end-users might request the tool be able to return whatever was read in, i.e., the original contents of go test ouput (with little modification).

E.g., in our pipeline we run go test ... | tparse -all -dump

This enables us to get a clear summary of packages and tests. If something goes wrong the -dump spits back everything that was read in from stdin with little modification.

It's possible there could be a flag for go test itself, e.g., -lessnoise that suppresses === RUN, === PAUSE and === CONT and that would reflect downstream in the test2json output. Just a thought.

[gopherbot]

Change https://go.dev/cl/443596 mentions this issue: testing: fix many test2json inaccuracies