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.

Fixes #38458

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>

1 files changed, 66 insertions, 15 deletions

diff --git a/src/testing/testing.go b/src/testing/testing.go
index 608bb39671..4a14d49a91 100644
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -325,6 +325,7 @@ var (
 	cpuListStr           *string
 	parallel             *int
 	testlog              *string
+	printer              *testPrinter
 
 	haveExamples bool // are there examples?
 
@@ -334,6 +335,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
@@ -354,10 +398,11 @@ type common struct {
 	cleanupPc   []uintptr           // The stack trace at the point where Cleanup was called.
 
 	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.
@@ -496,9 +541,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] == "" {
@@ -517,12 +559,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()
@@ -697,7 +739,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)...)
@@ -942,7 +991,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()
 	}
 
@@ -1001,7 +1050,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)
 				}
@@ -1100,7 +1149,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
@@ -1266,6 +1315,8 @@ func (m *M) Run() (code int) {
 		flag.Parse()
 	}
 
+	printer = newTestPrinter(Verbose())
+
 	if *parallel < 1 {
 		fmt.Fprintln(os.Stderr, "testing: -parallel can only be given a positive integer")
 		flag.Usage()
@@ -1309,12 +1360,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)
 		}
 	}
 }