testing: fix many test2json inaccuracies

Test2json is parsing the output stream from the test, which includes
package testing's own framing lines intermingled with other output,
in particular any output printed via fmt.Printf, println, and so on.
We have had recurring problems with unexpected partial output lines
causing a framing line to be missed.

A recent talk at GopherCon gave an example of an integration test
involving Docker that happened to print \r-terminated lines instead
of \n-terminated lines in some configurations, which in turn broke
test2json badly. (https://www.gophercon.com/agenda/session/944259)

There are also a variety of open reported issues with similar problems,
which this CL also addresses. The general approach is to add a new
testing flag -test.v=json that means to print additional output to help
test2json. And then test2json takes advantage of that output.

Among the fixes:

 - Identify testing framing more reliably, using ^V
   (golang#23036, golang#26325, golang#43683, GopherCon talk)
 - Test that output with \r\n endings is handled correctly
   (golang#43683, golang#34286)
 - Use === RUN in fuzz tests (golang#52636, golang#48132)
 - Add === RUN lines to note benchmark starts (golang#27764, golang#49505)
 - Print subtest --- PASS/FAIL lines as they happen (golang#29811)
 - Add === NAME lines to emit more test change events,
   such as when a subtest stops and the parent continues running.
 - Fix event shown in overall test failure (golang#27568)
 - Avoid interleaving of writes to os.Stdout and os.Stderr (golang#33419)

Fixes golang#23036.
Fixes golang#26325.
Fixes golang#27568.
Fixes golang#27764.
Fixes golang#29811.
Fixes golang#33419.
Fixes golang#34286.
Fixes golang#43683.
Fixes golang#49505.
Fixes golang#52636.

Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6
Reviewed-on: https://go-review.googlesource.com/c/go/+/443596
Auto-Submit: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>

src/cmd/go/internal/test/test.go

@@ -536,10 +536,41 @@ var (
 	testOutputDir    outputdirFlag                     // -outputdir flag
 	testShuffle      shuffleFlag                       // -shuffle flag
 	testTimeout      time.Duration                     // -timeout flag
-	testV            bool                              // -v flag
+	testV            testVFlag                         // -v flag
 	testVet          = vetFlag{flags: defaultVetFlags} // -vet flag
 )
 
+type testVFlag struct {
+	on   bool // -v is set in some form
+	json bool // -v=test2json is set, to make output better for test2json
+}
+
+func (*testVFlag) IsBoolFlag() bool { return true }
+
+func (f *testVFlag) Set(arg string) error {
+	if v, err := strconv.ParseBool(arg); err == nil {
+		f.on = v
+		f.json = false
+		return nil
+	}
+	if arg == "test2json" {
+		f.on = true
+		f.json = arg == "test2json"
+		return nil
+	}
+	return fmt.Errorf("invalid flag -test.v=%s", arg)
+}
+
+func (f *testVFlag) String() string {
+	if f.json {
+		return "test2json"
+	}
+	if f.on {
+		return "true"
+	}
+	return "false"
+}
+
 var (
 	testArgs []string
 	pkgArgs  []string
@@ -592,7 +623,7 @@ func testNeedBinary() bool {
 
 // testShowPass reports whether the output for a passing test should be shown.
 func testShowPass() bool {
-	return testV || (testList != "") || testHelp
+	return testV.on || testList != "" || testHelp
 }
 
 var defaultVetFlags = []string{
@@ -1309,7 +1340,11 @@ func (c *runCache) builderRunTest(b *work.Builder, ctx context.Context, a *work.
 		// not a pipe.
 		// TODO(golang.org/issue/29062): tests that exit with status 0 without
 		// printing a final result should fail.
-		fmt.Fprintf(cmd.Stdout, "FAIL\t%s\t%s\n", a.Package.ImportPath, t)
+		prefix := ""
+		if testJSON || testV.json {
+			prefix = "\x16"
+		}
+		fmt.Fprintf(cmd.Stdout, "%sFAIL\t%s\t%s\n", prefix, a.Package.ImportPath, t)
 	}
 
 	if cmd.Stdout != &buf {

src/cmd/go/internal/test/testflag.go

@@ -64,7 +64,7 @@ func init() {
 	cf.String("fuzztime", "", "")
 	cf.String("fuzzminimizetime", "", "")
 	cf.StringVar(&testTrace, "trace", "", "")
-	cf.BoolVar(&testV, "v", false, "")
+	cf.Var(&testV, "v", "")
 	cf.Var(&testShuffle, "shuffle", "")
 
 	for name := range passFlagToTest {
@@ -342,9 +342,11 @@ func testFlags(args []string) (packageNames, passToTest []string) {
 
 	var injectedFlags []string
 	if testJSON {
-		// If converting to JSON, we need the full output in order to pipe it to
-		// test2json.
-		injectedFlags = append(injectedFlags, "-test.v=true")
+		// If converting to JSON, we need the full output in order to pipe it to test2json.
+		// The -test.v=test2json flag is like -test.v=true but causes the test to add
+		// extra ^V characters before testing output lines and other framing,
+		// which helps test2json do a better job creating the JSON events.
+		injectedFlags = append(injectedFlags, "-test.v=test2json")
 		delete(addFromGOFLAGS, "v")
 		delete(addFromGOFLAGS, "test.v")
 	}

src/cmd/go/testdata/script/test_chatty_parallel_fail.txt

@@ -1,17 +1,21 @@
-# Run parallel chatty tests. Assert on CONT lines. This test makes sure that
-# multiple parallel outputs have the appropriate CONT lines between them.
+# Run parallel chatty tests.
+# Check that multiple parallel outputs continue running.
 ! go test -parallel 3 chatty_parallel_test.go -v
 
-stdout -count=1 '^=== CONT  TestChattyParallel/sub-0\n    chatty_parallel_test.go:38: error from sub-0$'
-stdout -count=1 '^=== CONT  TestChattyParallel/sub-1\n    chatty_parallel_test.go:38: error from sub-1$'
-stdout -count=1 '^=== CONT  TestChattyParallel/sub-2\n    chatty_parallel_test.go:38: error from sub-2$'
+stdout -count=1 '^=== CONT  TestChattyParallel/sub-0'
+stdout -count=1 '^=== CONT  TestChattyParallel/sub-1'
+stdout -count=1 '^=== CONT  TestChattyParallel/sub-2'
 
-# Run parallel chatty tests with -json. Assert on CONT lines as above - make
-# sure there are CONT lines before each output line.
+stdout -count=1 '^=== (CONT|NAME)  TestChattyParallel/sub-0\n    chatty_parallel_test.go:38: error from sub-0$'
+stdout -count=1 '^=== (CONT|NAME)  TestChattyParallel/sub-1\n    chatty_parallel_test.go:38: error from sub-1$'
+stdout -count=1 '^=== (CONT|NAME)  TestChattyParallel/sub-2\n    chatty_parallel_test.go:38: error from sub-2$'
+
+# Run parallel chatty tests with -json.
+# Check that each output is attributed to the right test.
 ! go test -json -parallel 3 chatty_parallel_test.go -v
-stdout -count=1 '{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-0","Output":"=== CONT  TestChattyParallel/sub-0\\n"}\n{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-0","Output":"    chatty_parallel_test.go:38: error from sub-0\\n"}'
-stdout -count=1 '{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-1","Output":"=== CONT  TestChattyParallel/sub-1\\n"}\n{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-1","Output":"    chatty_parallel_test.go:38: error from sub-1\\n"}'
-stdout -count=1 '{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"=== CONT  TestChattyParallel/sub-2\\n"}\n{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"    chatty_parallel_test.go:38: error from sub-2\\n"}'
+stdout -count=1 '"Test":"TestChattyParallel/sub-0","Output":"    chatty_parallel_test.go:38: error from sub-0\\n"'
+stdout -count=1 '"Test":"TestChattyParallel/sub-1","Output":"    chatty_parallel_test.go:38: error from sub-1\\n"'
+stdout -count=1 '"Test":"TestChattyParallel/sub-2","Output":"    chatty_parallel_test.go:38: error from sub-2\\n"'
 
 -- chatty_parallel_test.go --
 package chatty_parallel_test

src/cmd/go/testdata/script/test_chatty_parallel_success.txt

@@ -1,16 +1,16 @@
-# Run parallel chatty tests. Assert on CONT lines. This test makes sure that
-# multiple parallel outputs have the appropriate CONT lines between them.
+# Run parallel chatty tests. Assert on CONT or NAME lines. This test makes sure that
+# multiple parallel outputs have the appropriate test name lines between them.
 go test -parallel 3 chatty_parallel_test.go -v
-stdout -count=2 '^=== CONT  TestChattyParallel/sub-0\n    chatty_parallel_test.go:32: this is sub-0$'
-stdout -count=2 '^=== CONT  TestChattyParallel/sub-1\n    chatty_parallel_test.go:32: this is sub-1$'
-stdout -count=2 '^=== CONT  TestChattyParallel/sub-2\n    chatty_parallel_test.go:32: this is sub-2$'
+stdout -count=2 '^=== (CONT|NAME)  TestChattyParallel/sub-0\n    chatty_parallel_test.go:32: this is sub-0$'
+stdout -count=2 '^=== (CONT|NAME)  TestChattyParallel/sub-1\n    chatty_parallel_test.go:32: this is sub-1$'
+stdout -count=2 '^=== (CONT|NAME)  TestChattyParallel/sub-2\n    chatty_parallel_test.go:32: this is sub-2$'
 
-# Run parallel chatty tests with -json. Assert on CONT lines as above - make
-# sure there are CONT lines before each output line.
+# Run parallel chatty tests with -json.
+# Assert test2json has properly attributed output.
 go test -json -parallel 3 chatty_parallel_test.go -v
-stdout -count=2 '{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-0","Output":"=== CONT  TestChattyParallel/sub-0\\n"}\n{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-0","Output":"    chatty_parallel_test.go:32: this is sub-0\\n"}'
-stdout -count=2 '{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-1","Output":"=== CONT  TestChattyParallel/sub-1\\n"}\n{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-1","Output":"    chatty_parallel_test.go:32: this is sub-1\\n"}'
-stdout -count=2 '{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"=== CONT  TestChattyParallel/sub-2\\n"}\n{"Time":"[0-9TZ:.+-]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"    chatty_parallel_test.go:32: this is sub-2\\n"}'
+stdout -count=2 '"Test":"TestChattyParallel/sub-0","Output":"    chatty_parallel_test.go:32: this is sub-0\\n"'
+stdout -count=2 '"Test":"TestChattyParallel/sub-1","Output":"    chatty_parallel_test.go:32: this is sub-1\\n"'
+stdout -count=2 '"Test":"TestChattyParallel/sub-2","Output":"    chatty_parallel_test.go:32: this is sub-2\\n"'
 
 -- chatty_parallel_test.go --
 package chatty_parallel_test

src/cmd/go/testdata/script/test_chatty_parallel_success_run.txt

@@ -1,8 +1,8 @@
-# Run parallel chatty tests. Assert on CONT lines. This test makes sure that
+# Run parallel chatty tests. Assert on CONT or NAME lines. This test makes sure that
 # multiple parallel outputs have the appropriate CONT lines between them.
 go test -parallel 3 chatty_parallel -v
 
-stdout '=== RUN   TestInterruptor/interruption\n=== CONT  TestLog\n    chatty_parallel_test.go:28: this is the second TestLog log\n--- PASS: Test(Log|Interruptor) \([0-9.]{4}s\)'
+stdout '=== RUN   TestInterruptor/interruption\n=== (CONT|NAME)  TestLog\n    chatty_parallel_test.go:28: this is the second TestLog log\n--- PASS: Test(Log|Interruptor) \([0-9.]{4}s\)'
 
 -- go.mod --
 module chatty_parallel

src/cmd/go/testdata/script/test_json_panic_exit.txt

@@ -4,7 +4,7 @@
 
 # 'go test -json' should say a test passes if it says it passes.
 go test -json ./pass
-stdout '"Action":"pass".*\n\z'
+stdout '"Action":"pass","Package":"[^"]*","Elapsed":[^"]*}\n\z'
 ! stdout '"Test":.*\n\z'
 
 # 'go test -json' should say a test passes if it exits 0 and prints nothing.

src/cmd/go/testdata/script/test_json_prints.txt

@@ -0,0 +1,48 @@
+go test -json
+
+stdout '"Action":"output","Package":"p","Output":"M1"}'
+stdout '"Action":"output","Package":"p","Test":"Test","Output":"=== RUN   Test\\n"}'
+stdout '"Action":"output","Package":"p","Test":"Test","Output":"T1"}'
+stdout '"Action":"output","Package":"p","Test":"Test/Sub1","Output":"=== RUN   Test/Sub1\\n"}'
+stdout '"Action":"output","Package":"p","Test":"Test/Sub1","Output":"Sub1    x_test.go:19: SubLog1\\n"}'
+stdout '"Action":"output","Package":"p","Test":"Test/Sub1","Output":"Sub2"}'
+stdout '"Action":"output","Package":"p","Test":"Test/Sub1","Output":"--- PASS: Test/Sub1 \([\d.]+s\)\\n"}'
+stdout '"Action":"pass","Package":"p","Test":"Test/Sub1","Elapsed"'
+stdout '"Action":"output","Package":"p","Test":"Test/Sub3","Output":"foo bar"}'
+stdout '"Action":"output","Package":"p","Test":"Test/Sub3","Output":"baz\\n"}'
+stdout '"Action":"output","Package":"p","Test":"Test","Output":"T2"}'
+stdout '"Action":"output","Package":"p","Test":"Test","Output":"--- PASS: Test \([\d.]+s\)\\n"}'
+stdout '"Action":"pass","Package":"p","Test":"Test","Elapsed"'
+stdout '"Action":"output","Package":"p","Output":"M2ok  \\tp\\t[\d.]+s\\n"}'
+stdout '"Action":"pass","Package":"p","Elapsed"'
+
+-- go.mod --
+module p
+
+-- x_test.go --
+package p
+
+import (
+	"os"
+	"testing"
+)
+
+func TestMain(m *testing.M) {
+	print("M1")
+	code := m.Run()
+	print("M2")
+	os.Exit(code)
+}
+
+func Test(t *testing.T) {
+	print("T1")
+	t.Run("Sub1", func(t *testing.T) {
+		print("Sub1")
+		t.Log("SubLog1")
+		print("Sub2")
+	})
+	t.Run("Sub3", func(t *testing.T) {
+		print("\x16foo bar\x16baz\n")
+	})
+	print("T2")
+}

src/cmd/go/testdata/script/test_json_timeout.txt

@@ -0,0 +1,19 @@
+! go test -json -timeout=1ms
+
+stdout '"Action":"output","Package":"p","Output":"FAIL\\tp\\t'
+stdout '"Action":"fail","Package":"p","Elapsed":'
+
+-- go.mod --
+module p
+
+-- x_test.go --
+package p
+
+import (
+	"testing"
+	"time"
+)
+
+func Test(t *testing.T) {
+	time.Sleep(1*time.Hour)
+}