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

10 files changed, 370 insertions, 84 deletions

diff --git a/src/cmd/go/testdata/script/test_benchmark_chatty_fail.txt b/src/cmd/go/testdata/script/test_benchmark_chatty_fail.txt
new file mode 100644
index 0000000000..6031eadd0a
--- /dev/null
+++ b/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)
+        })
+    }
+}
\ No newline at end of file
diff --git a/src/cmd/go/testdata/script/test_benchmark_chatty_success.txt b/src/cmd/go/testdata/script/test_benchmark_chatty_success.txt
new file mode 100644
index 0000000000..a1c0d6545a
--- /dev/null
+++ b/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)
+            }
+        })
+    }
+}
\ No newline at end of file
diff --git a/src/cmd/go/testdata/script/test_chatty_fail.txt b/src/cmd/go/testdata/script/test_chatty_fail.txt
new file mode 100644
index 0000000000..a5ef559c77
--- /dev/null
+++ b/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)
+        })
+    }
+}
\ No newline at end of file
diff --git a/src/cmd/go/testdata/script/test_chatty_parallel_fail.txt b/src/cmd/go/testdata/script/test_chatty_parallel_fail.txt
new file mode 100644
index 0000000000..5c51a02846
--- /dev/null
+++ b/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
+		})
+	}
+}
diff --git a/src/cmd/go/testdata/script/test_chatty_parallel_success.txt b/src/cmd/go/testdata/script/test_chatty_parallel_success.txt
new file mode 100644
index 0000000000..0f97d4c221
--- /dev/null
+++ b/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
+			}
+		})
+	}
+}
diff --git a/src/cmd/go/testdata/script/test_chatty_success.txt b/src/cmd/go/testdata/script/test_chatty_success.txt
new file mode 100644
index 0000000000..8bfa569f80
--- /dev/null
+++ b/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)
+            }
+        })
+    }
+}
\ No newline at end of file
diff --git a/src/cmd/go/testdata/script/test_regexps.txt b/src/cmd/go/testdata/script/test_regexps.txt
index 39dedbf06f..a616195cab 100644
--- a/src/cmd/go/testdata/script/test_regexps.txt
+++ b/src/cmd/go/testdata/script/test_regexps.txt
@@ -4,28 +4,28 @@ 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.
@@ -33,7 +33,7 @@ stdout -count=1 '^\s+BenchmarkXX: z_test.go:18: LOG: XX running N=1$'
 # 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
diff --git a/src/testing/benchmark.go b/src/testing/benchmark.go
index 88ba0f0242..52766005bf 100644
--- a/src/testing/benchmark.go
+++ b/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,
diff --git a/src/testing/sub_test.go b/src/testing/sub_test.go
index 95f8220f81..8eb0084b1c 100644
--- a/src/testing/sub_test.go
+++ b/src/testing/sub_test.go
@@ -438,8 +438,6 @@ func TestTRun(t *T) {
 	}, {
 		// A chatty test should always log with fmt.Print, even if the
 		// parent test has completed.
-		// TODO(deklerk) Capture the log of fmt.Print and assert that the
-		// subtest message is not lost.
 		desc:   "log in finished sub test with chatty",
 		ok:     false,
 		chatty: true,
@@ -477,35 +475,37 @@ func TestTRun(t *T) {
 		},
 	}}
 	for _, tc := range testCases {
-		ctx := newTestContext(tc.maxPar, newMatcher(regexp.MatchString, "", ""))
-		buf := &bytes.Buffer{}
-		root := &T{
-			common: common{
-				signal: make(chan bool),
-				name:   "Test",
-				w:      buf,
-				chatty: tc.chatty,
-			},
-			context: ctx,
-		}
-		ok := root.Run(tc.desc, tc.f)
-		ctx.release()
+		t.Run(tc.desc, func(t *T) {
+			ctx := newTestContext(tc.maxPar, newMatcher(regexp.MatchString, "", ""))
+			buf := &bytes.Buffer{}
+			root := &T{
+				common: common{
+					signal: make(chan bool),
+					name:   "Test",
+					w:      buf,
+					chatty: tc.chatty,
+				},
+				context: ctx,
+			}
+			ok := root.Run(tc.desc, tc.f)
+			ctx.release()
 
-		if ok != tc.ok {
-			t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, tc.ok)
-		}
-		if ok != !root.Failed() {
-			t.Errorf("%s:root failed: got %v; want %v", tc.desc, !ok, root.Failed())
-		}
-		if ctx.running != 0 || ctx.numWaiting != 0 {
-			t.Errorf("%s:running and waiting non-zero: got %d and %d", tc.desc, ctx.running, ctx.numWaiting)
-		}
-		got := strings.TrimSpace(buf.String())
-		want := strings.TrimSpace(tc.output)
-		re := makeRegexp(want)
-		if ok, err := regexp.MatchString(re, got); !ok || err != nil {
-			t.Errorf("%s:output:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
-		}
+			if ok != tc.ok {
+				t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, tc.ok)
+			}
+			if ok != !root.Failed() {
+				t.Errorf("%s:root failed: got %v; want %v", tc.desc, !ok, root.Failed())
+			}
+			if ctx.running != 0 || ctx.numWaiting != 0 {
+				t.Errorf("%s:running and waiting non-zero: got %d and %d", tc.desc, ctx.running, ctx.numWaiting)
+			}
+			got := strings.TrimSpace(buf.String())
+			want := strings.TrimSpace(tc.output)
+			re := makeRegexp(want)
+			if ok, err := regexp.MatchString(re, got); !ok || err != nil {
+				t.Errorf("%s:output:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
+			}
+		})
 	}
 }
 
@@ -655,43 +655,45 @@ func TestBRun(t *T) {
 		},
 	}}
 	for _, tc := range testCases {
-		var ok bool
-		buf := &bytes.Buffer{}
-		// This is almost like the Benchmark function, except that we override
-		// the benchtime and catch the failure result of the subbenchmark.
-		root := &B{
-			common: common{
-				signal: make(chan bool),
-				name:   "root",
-				w:      buf,
-				chatty: tc.chatty,
-			},
-			benchFunc: func(b *B) { ok = b.Run("test", tc.f) }, // Use Run to catch failure.
-			benchTime: benchTimeFlag{d: 1 * time.Microsecond},
-		}
-		root.runN(1)
-		if ok != !tc.failed {
-			t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, !tc.failed)
-		}
-		if !ok != root.Failed() {
-			t.Errorf("%s:root failed: got %v; want %v", tc.desc, !ok, root.Failed())
-		}
-		// All tests are run as subtests
-		if root.result.N != 1 {
-			t.Errorf("%s: N for parent benchmark was %d; want 1", tc.desc, root.result.N)
-		}
-		got := strings.TrimSpace(buf.String())
-		want := strings.TrimSpace(tc.output)
-		re := makeRegexp(want)
-		if ok, err := regexp.MatchString(re, got); !ok || err != nil {
-			t.Errorf("%s:output:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
-		}
+		t.Run(tc.desc, func(t *T) {
+			var ok bool
+			buf := &bytes.Buffer{}
+			// This is almost like the Benchmark function, except that we override
+			// the benchtime and catch the failure result of the subbenchmark.
+			root := &B{
+				common: common{
+					signal: make(chan bool),
+					name:   "root",
+					w:      buf,
+					chatty: tc.chatty,
+				},
+				benchFunc: func(b *B) { ok = b.Run("test", tc.f) }, // Use Run to catch failure.
+				benchTime: benchTimeFlag{d: 1 * time.Microsecond},
+			}
+			root.runN(1)
+			if ok != !tc.failed {
+				t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, !tc.failed)
+			}
+			if !ok != root.Failed() {
+				t.Errorf("%s:root failed: got %v; want %v", tc.desc, !ok, root.Failed())
+			}
+			// All tests are run as subtests
+			if root.result.N != 1 {
+				t.Errorf("%s: N for parent benchmark was %d; want 1", tc.desc, root.result.N)
+			}
+			got := strings.TrimSpace(buf.String())
+			want := strings.TrimSpace(tc.output)
+			re := makeRegexp(want)
+			if ok, err := regexp.MatchString(re, got); !ok || err != nil {
+				t.Errorf("%s:output:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
+			}
+		})
 	}
 }
 
 func makeRegexp(s string) string {
 	s = regexp.QuoteMeta(s)
-	s = strings.ReplaceAll(s, ":NNN:", `:\d\d\d:`)
+	s = strings.ReplaceAll(s, ":NNN:", `:\d\d\d\d?:`)
 	s = strings.ReplaceAll(s, "N\\.NNs", `\d*\.\d*s`)
 	return s
 }
diff --git a/src/testing/testing.go b/src/testing/testing.go
index 966cafbd3a..787caf1c83 100644
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -320,6 +320,7 @@ var (
 	cpuListStr           *string
 	parallel             *int
 	testlog              *string
+	printer              *testPrinter
 
 	haveExamples bool // are there examples?
 
@@ -329,6 +330,49 @@ var (
 	numFailed uint32 // number of test failures
 )
 
+type testPrinter struct {
+	chatty bool
+
+	lastNameMu sync.Mutex // guards lastName
+	lastName   string     // last printed test name in chatty mode
+}
+
+func newTestPrinter(chatty bool) *testPrinter {
+	return &testPrinter{
+		chatty: chatty,
+	}
+}
+
+func (p *testPrinter) Print(testName, out string) {
+	p.Fprint(os.Stdout, testName, out)
+}
+
+func (p *testPrinter) Fprint(w io.Writer, testName, out string) {
+	if !p.chatty || strings.HasPrefix(out, "--- PASS") || strings.HasPrefix(out, "--- FAIL") {
+		fmt.Fprint(w, out)
+		return
+	}
+
+	p.lastNameMu.Lock()
+	defer p.lastNameMu.Unlock()
+
+	if strings.HasPrefix(out, "=== CONT") || strings.HasPrefix(out, "=== RUN") {
+		p.lastName = testName
+		fmt.Fprint(w, out)
+		return
+	}
+
+	if p.lastName == "" {
+		p.lastName = testName
+	} else if p.lastName != testName {
+		// Always printed as-is, with 0 decoration or indentation. So, we skip
+		// printing to w.
+		fmt.Printf("=== CONT  %s\n", testName)
+		p.lastName = testName
+	}
+	fmt.Fprint(w, out)
+}
+
 // The maximum number of stack frames to go through when skipping helper functions for
 // the purpose of decorating log messages.
 const maxStackLen = 50
@@ -347,10 +391,11 @@ type common struct {
 	cleanup func()              // optional function to be called at the end of the test
 
 	chatty     bool   // A copy of the chatty flag.
+	bench      bool   // Whether the current test is a benchmark.
 	finished   bool   // Test function has completed.
-	hasSub     int32  // written atomically
-	raceErrors int    // number of races detected during test
-	runner     string // function name of tRunner running the test
+	hasSub     int32  // Written atomically.
+	raceErrors int    // Number of races detected during test.
+	runner     string // Function name of tRunner running the test.
 
 	parent   *common
 	level    int       // Nesting depth of test or benchmark.
@@ -480,9 +525,6 @@ func (c *common) decorate(s string, skip int) string {
 	buf := new(strings.Builder)
 	// Every line is indented at least 4 spaces.
 	buf.WriteString("    ")
-	if c.chatty {
-		fmt.Fprintf(buf, "%s: ", c.name)
-	}
 	fmt.Fprintf(buf, "%s:%d: ", file, line)
 	lines := strings.Split(s, "\n")
 	if l := len(lines); l > 1 && lines[l-1] == "" {
@@ -501,12 +543,12 @@ func (c *common) decorate(s string, skip int) string {
 
 // flushToParent writes c.output to the parent after first writing the header
 // with the given format and arguments.
-func (c *common) flushToParent(format string, args ...interface{}) {
+func (c *common) flushToParent(testName, format string, args ...interface{}) {
 	p := c.parent
 	p.mu.Lock()
 	defer p.mu.Unlock()
 
-	fmt.Fprintf(p.w, format, args...)
+	printer.Fprint(p.w, testName, fmt.Sprintf(format, args...))
 
 	c.mu.Lock()
 	defer c.mu.Unlock()
@@ -680,7 +722,14 @@ func (c *common) logDepth(s string, depth int) {
 		panic("Log in goroutine after " + c.name + " has completed")
 	} else {
 		if c.chatty {
-			fmt.Print(c.decorate(s, depth+1))
+			if c.bench {
+				// Benchmarks don't print === CONT, so we should skip the test
+				// printer and just print straight to stdout.
+				fmt.Print(c.decorate(s, depth+1))
+			} else {
+				printer.Print(c.name, c.decorate(s, depth+1))
+			}
+
 			return
 		}
 		c.output = append(c.output, c.decorate(s, depth+1)...)
@@ -873,7 +922,7 @@ func (t *T) Parallel() {
 		for ; root.parent != nil; root = root.parent {
 		}
 		root.mu.Lock()
-		fmt.Fprintf(root.w, "=== CONT  %s\n", t.name)
+		printer.Fprint(root.w, t.name, fmt.Sprintf("=== CONT  %s\n", t.name))
 		root.mu.Unlock()
 	}
 
@@ -932,7 +981,7 @@ func tRunner(t *T, fn func(t *T)) {
 				root.duration += time.Since(root.start)
 				d := root.duration
 				root.mu.Unlock()
-				root.flushToParent("--- FAIL: %s (%s)\n", root.name, fmtDuration(d))
+				root.flushToParent(root.name, "--- FAIL: %s (%s)\n", root.name, fmtDuration(d))
 				if r := root.parent.runCleanup(recoverAndReturnPanic); r != nil {
 					fmt.Fprintf(root.parent.w, "cleanup panicked with %v", r)
 				}
@@ -1031,7 +1080,7 @@ func (t *T) Run(name string, f func(t *T)) bool {
 		for ; root.parent != nil; root = root.parent {
 		}
 		root.mu.Lock()
-		fmt.Fprintf(root.w, "=== RUN   %s\n", t.name)
+		printer.Fprint(root.w, t.name, fmt.Sprintf("=== RUN   %s\n", t.name))
 		root.mu.Unlock()
 	}
 	// Instead of reducing the running count of this test before calling the
@@ -1179,6 +1228,8 @@ func (m *M) Run() int {
 		flag.Parse()
 	}
 
+	printer = newTestPrinter(Verbose())
+
 	if *parallel < 1 {
 		fmt.Fprintln(os.Stderr, "testing: -parallel can only be given a positive integer")
 		flag.Usage()
@@ -1218,12 +1269,12 @@ func (t *T) report() {
 	dstr := fmtDuration(t.duration)
 	format := "--- %s: %s (%s)\n"
 	if t.Failed() {
-		t.flushToParent(format, "FAIL", t.name, dstr)
+		t.flushToParent(t.name, format, "FAIL", t.name, dstr)
 	} else if t.chatty {
 		if t.Skipped() {
-			t.flushToParent(format, "SKIP", t.name, dstr)
+			t.flushToParent(t.name, format, "SKIP", t.name, dstr)
 		} else {
-			t.flushToParent(format, "PASS", t.name, dstr)
+			t.flushToParent(t.name, format, "PASS", t.name, dstr)
 		}
 	}
 }