[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>

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

@@ -0,0 +1,32 @@
+# Run chatty tests. Assert on CONT lines.
+! go test chatty_test.go -v -bench . chatty_bench
+
+# Sanity check that output occurs.
+stdout -count=2 'this is sub-0'
+stdout -count=2 'this is sub-1'
+stdout -count=2 'this is sub-2'
+stdout -count=1 'error from sub-0'
+stdout -count=1 'error from sub-1'
+stdout -count=1 'error from sub-2'
+
+# Benchmarks should not print CONT.
+! stdout CONT
+
+-- chatty_test.go --
+package chatty_bench
+
+import (
+	"testing"
+	"fmt"
+)
+
+func BenchmarkChatty(b *testing.B) {
+    for i := 0; i < 3; i++ {
+        b.Run(fmt.Sprintf("sub-%d", i), func(b *testing.B) {
+            for j := 0; j < 2; j++ {
+                b.Logf("this is sub-%d", i)
+            }
+            b.Errorf("error from sub-%d", i)
+        })
+    }
+}

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

@@ -0,0 +1,29 @@
+# Run chatty tests. Assert on CONT lines.
+go test chatty_test.go -v -bench . chatty_bench
+
+# Sanity check that output happens. We don't provide -count because the amount
+# of output is variable.
+stdout 'this is sub-0'
+stdout 'this is sub-1'
+stdout 'this is sub-2'
+
+# Benchmarks should not print CONT.
+! stdout CONT
+
+-- chatty_test.go --
+package chatty_bench
+
+import (
+	"testing"
+	"fmt"
+)
+
+func BenchmarkChatty(b *testing.B) {
+    for i := 0; i < 3; i++ {
+        b.Run(fmt.Sprintf("sub-%d", i), func(b *testing.B) {
+            for j := 0; j < 2; j++ {
+                b.Logf("this is sub-%d", i)
+            }
+        })
+    }
+}

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

@@ -0,0 +1,32 @@
+# Run chatty tests. Assert on CONT lines.
+! go test chatty_test.go -v
+
+# Sanity check that output occurs.
+stdout -count=2 'this is sub-0'
+stdout -count=2 'this is sub-1'
+stdout -count=2 'this is sub-2'
+stdout -count=1 'error from sub-0'
+stdout -count=1 'error from sub-1'
+stdout -count=1 'error from sub-2'
+
+# Non-parallel tests should not print CONT.
+! stdout CONT
+
+-- chatty_test.go --
+package chatty_test
+
+import (
+	"testing"
+	"fmt"
+)
+
+func TestChatty(t *testing.T) {
+    for i := 0; i < 3; i++ {
+        t.Run(fmt.Sprintf("sub-%d", i), func(t *testing.T) {
+            for j := 0; j < 2; j++ {
+                t.Logf("this is sub-%d", i)
+            }
+            t.Errorf("error from sub-%d", i)
+        })
+    }
+}

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

@@ -0,0 +1,58 @@
+# Run parallel chatty tests. Assert on CONT lines. This test makes sure that
+# multiple parallel outputs have the appropriate CONT lines between them.
+! 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$'
+
+# Run parallel chatty tests with -json. Assert on CONT lines as above - make
+# sure there are CONT lines before each output line.
+! go test -json -parallel 3 chatty_parallel_test.go -v
+stdout -count=1 '{"Time":"[0-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-0","Output":"=== CONT  TestChattyParallel/sub-0\\n"}\n{"Time":"[0-9-TZ:.]{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-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-1","Output":"=== CONT  TestChattyParallel/sub-1\\n"}\n{"Time":"[0-9-TZ:.]{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-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"=== CONT  TestChattyParallel/sub-2\\n"}\n{"Time":"[0-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"    chatty_parallel_test.go:38: error from sub-2\\n"}'
+
+-- chatty_parallel_test.go --
+package chatty_paralell_test
+
+import (
+	"testing"
+	"fmt"
+	"flag"
+)
+
+// This test ensures the the order of CONT lines in parallel chatty tests.
+func TestChattyParallel(t *testing.T) {
+	t.Parallel()
+
+	// The number of concurrent tests running. This is closely tied to the
+	// -parallel test flag, so we grab it from the flag rather than setting it
+	// to some constant.
+	parallel := flag.Lookup("test.parallel").Value.(flag.Getter).Get().(int)
+
+	// ready is a synchronization mechanism that causes subtests to execute
+	// round robin.
+	ready := make([]chan bool, parallel)
+	for i := range ready {
+		ready[i] = make(chan bool, 1)
+	}
+	ready[0] <- true
+
+	for i := range ready {
+		i := i
+		t.Run(fmt.Sprintf("sub-%d", i), func(t *testing.T) {
+			t.Parallel()
+
+			// Some basic log output to precede the failures.
+			<-ready[i]
+			t.Logf("this is sub-%d", i)
+			ready[(i+1)%len(ready)] <- true
+
+			// The actual failure messages we care about.
+			<-ready[i]
+			t.Errorf("error from sub-%d", i)
+			ready[(i+1)%len(ready)] <- true
+		})
+	}
+}

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

@@ -0,0 +1,52 @@
+# Run parallel chatty tests. Assert on CONT lines. This test makes sure that
+# multiple parallel outputs have the appropriate CONT 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$'
+
+# Run parallel chatty tests with -json. Assert on CONT lines as above - make
+# sure there are CONT lines before each output line.
+go test -json -parallel 3 chatty_parallel_test.go -v
+stdout -count=2 '{"Time":"[0-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-0","Output":"=== CONT  TestChattyParallel/sub-0\\n"}\n{"Time":"[0-9-TZ:.]{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-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-1","Output":"=== CONT  TestChattyParallel/sub-1\\n"}\n{"Time":"[0-9-TZ:.]{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-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"=== CONT  TestChattyParallel/sub-2\\n"}\n{"Time":"[0-9-TZ:.]{20,40}","Action":"output","Package":"command-line-arguments","Test":"TestChattyParallel/sub-2","Output":"    chatty_parallel_test.go:32: this is sub-2\\n"}'
+
+-- chatty_parallel_test.go --
+package chatty_paralell_test
+
+import (
+	"testing"
+	"fmt"
+	"flag"
+)
+
+// This test ensures the the order of CONT lines in parallel chatty tests.
+func TestChattyParallel(t *testing.T) {
+	t.Parallel()
+
+	// The number of concurrent tests running. This is closely tied to the
+	// -parallel test flag, so we grab it from the flag rather than setting it
+	// to some constant.
+	parallel := flag.Lookup("test.parallel").Value.(flag.Getter).Get().(int)
+
+	// ready is a synchronization mechanism that causes subtests to execute
+	// round robin.
+	ready := make([]chan bool, parallel)
+	for i := range ready {
+		ready[i] = make(chan bool, 1)
+	}
+	ready[0] <- true
+
+	for i := range ready {
+		i := i
+		t.Run(fmt.Sprintf("sub-%d", i), func(t *testing.T) {
+			t.Parallel()
+			for j := 0; j < 2; j++ {
+				<-ready[i]
+				t.Logf("this is sub-%d", i)
+				ready[(i+1)%len(ready)] <- true
+			}
+		})
+	}
+}

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

@@ -0,0 +1,27 @@
+# Run chatty tests. Assert on CONT lines.
+go test chatty_test.go -v
+
+# Non-parallel tests should not print CONT.
+! stdout CONT
+
+# The assertion is condensed into one line so that it precisely matches output,
+# rather than skipping lines and allow rogue CONT lines.
+stdout '=== RUN   TestChatty\n=== RUN   TestChatty/sub-0\n    chatty_test.go:12: this is sub-0\n    chatty_test.go:12: this is sub-0\n=== RUN   TestChatty/sub-1\n    chatty_test.go:12: this is sub-1\n    chatty_test.go:12: this is sub-1\n=== RUN   TestChatty/sub-2\n    chatty_test.go:12: this is sub-2\n    chatty_test.go:12: this is sub-2\n--- PASS: TestChatty'
+
+-- chatty_test.go --
+package chatty_test
+
+import (
+	"testing"
+	"fmt"
+)
+
+func TestChatty(t *testing.T) {
+    for i := 0; i < 3; i++ {
+        t.Run(fmt.Sprintf("sub-%d", i), func(t *testing.T) {
+            for j := 0; j < 2; j++ {
+                t.Logf("this is sub-%d", i)
+            }
+        })
+    }
+}

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

@@ -4,36 +4,36 @@ go test -cpu=1 -run=X/Y -bench=X/Y -count=2 -v testregexp
 
 # TestX is run, twice
 stdout -count=2 '^=== RUN   TestX$'
-stdout -count=2 '^    TestX: x_test.go:6: LOG: X running$'
+stdout -count=2 '^    x_test.go:6: LOG: X running$'
 
 # TestX/Y is run, twice
 stdout -count=2 '^=== RUN   TestX/Y$'
-stdout -count=2 '^    TestX/Y: x_test.go:8: LOG: Y running$'
+stdout -count=2 '^    x_test.go:8: LOG: Y running$'
 
 # TestXX is run, twice
 stdout -count=2 '^=== RUN   TestXX$'
-stdout -count=2 '^    TestXX: z_test.go:10: LOG: XX running'
+stdout -count=2 '^    z_test.go:10: LOG: XX running'
 
 # TestZ is not run
 ! stdout '^=== RUN   TestZ$'
 
 # BenchmarkX is run with N=1 once, only to discover what sub-benchmarks it has,
 # and should not print a final summary line.
-stdout -count=1 '^\s+BenchmarkX: x_test.go:13: LOG: X running N=1$'
+stdout -count=1 '^    x_test.go:13: LOG: X running N=1$'
 ! stdout '^\s+BenchmarkX: x_test.go:13: LOG: X running N=\d\d+'
 ! stdout 'BenchmarkX\s+\d+'
 
 # Same for BenchmarkXX.
-stdout -count=1 '^\s+BenchmarkXX: z_test.go:18: LOG: XX running N=1$'
-! stdout  '^\s+BenchmarkXX: z_test.go:18: LOG: XX running N=\d\d+'
+stdout -count=1 '^    z_test.go:18: LOG: XX running N=1$'
+! stdout  '^    z_test.go:18: LOG: XX running N=\d\d+'
 ! stdout 'BenchmarkXX\s+\d+'
 
 # BenchmarkX/Y is run in full twice due to -count=2.
 # "Run in full" means that it runs for approximately the default benchtime,
 # but may cap out at N=1e9.
 # We don't actually care what the final iteration count is, but it should be
 # a large number, and the last iteration count prints right before the results.
-stdout -count=2 '^\s+BenchmarkX/Y: x_test.go:15: LOG: Y running N=[1-9]\d{4,}\nBenchmarkX/Y\s+\d+'
+stdout -count=2 '^    x_test.go:15: LOG: Y running N=[1-9]\d{4,}\nBenchmarkX/Y\s+\d+'
 
 -- testregexp/x_test.go --
 package x

src/testing/benchmark.go

@@ -526,6 +526,7 @@ func runBenchmarks(importPath string, matchString func(pat, str string) (bool, e
 			name:   "Main",
 			w:      os.Stdout,
 			chatty: *chatty,
+			bench:  true,
 		},
 		importPath: importPath,
 		benchFunc: func(b *B) {
@@ -559,6 +560,7 @@ func (ctx *benchContext) processBench(b *B) {
 						name:   b.name,
 						w:      b.w,
 						chatty: b.chatty,
+						bench:  true,
 					},
 					benchFunc: b.benchFunc,
 					benchTime: b.benchTime,
@@ -624,6 +626,7 @@ func (b *B) Run(name string, f func(b *B)) bool {
 			creator: pc[:n],
 			w:       b.w,
 			chatty:  b.chatty,
+			bench:   true,
 		},
 		importPath: b.importPath,
 		benchFunc:  f,