testing: flush test summaries to stdout atomically when streaming output

While debugging #40771, I realized that the chatty printer should only
ever print to a single io.Writer (normally os.Stdout). The other
Writer implementations in the chain write to local buffers, but if we
wrote a test's output to a local buffer, then we did *not* write it to
stdout and we should not store it as the most recently logged test.

Because the chatty printer should only ever print to one place, it
shouldn't receive an io.Writer as an argument — rather, it shouldn't
be used at all for destinations other than the main output stream.

On the other hand, when we flush the output buffer to stdout in the
top-level flushToParent call, it is important that we not allow some
other test's output to intrude between the test summary header and the
remainder of the test's output. cmd/test2json doesn't know how to
parse such an intrusion, and it's confusing to humans too.

No test because I couldn't reproduce the user-reported error without
modifying the testing package. (This behavior seems to be very
sensitive to output size and/or goroutine scheduling.)

Fixes #40771
Updates #38458

Change-Id: Ic19bf1d535672b096ba1c8583a3b74aab6d6d766
Reviewed-on: https://go-review.googlesource.com/c/go/+/249026
Run-TryBot: Bryan C. Mills <bcmills@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Jay Conrod <jayconrod@google.com>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

Author: Bryan C. Mills

src/testing/benchmark.go

@@ -242,7 +242,7 @@ func (b *B) run1() bool {
 		if b.skipped {
 			tag = "SKIP"
 		}
-		if b.chatty && (len(b.output) > 0 || b.finished) {
+		if b.chatty != nil && (len(b.output) > 0 || b.finished) {
 			b.trimOutput()
 			fmt.Fprintf(b.w, "--- %s: %s\n%s", tag, b.name, b.output)
 		}
@@ -523,10 +523,9 @@ func runBenchmarks(importPath string, matchString func(pat, str string) (bool, e
 	}
 	main := &B{
 		common: common{
-			name:   "Main",
-			w:      os.Stdout,
-			chatty: *chatty,
-			bench:  true,
+			name:  "Main",
+			w:     os.Stdout,
+			bench: true,
 		},
 		importPath: importPath,
 		benchFunc: func(b *B) {
@@ -537,6 +536,9 @@ func runBenchmarks(importPath string, matchString func(pat, str string) (bool, e
 		benchTime: benchTime,
 		context:   ctx,
 	}
+	if Verbose() {
+		main.chatty = newChattyPrinter(main.w)
+	}
 	main.runN(1)
 	return !main.failed
 }
@@ -549,7 +551,7 @@ func (ctx *benchContext) processBench(b *B) {
 			benchName := benchmarkName(b.name, procs)
 
 			// If it's chatty, we've already printed this information.
-			if !b.chatty {
+			if b.chatty == nil {
 				fmt.Fprintf(b.w, "%-*s\t", ctx.maxLen, benchName)
 			}
 			// Recompute the running time for all but the first iteration.
@@ -576,7 +578,7 @@ func (ctx *benchContext) processBench(b *B) {
 				continue
 			}
 			results := r.String()
-			if b.chatty {
+			if b.chatty != nil {
 				fmt.Fprintf(b.w, "%-*s\t", ctx.maxLen, benchName)
 			}
 			if *benchmarkMemory || b.showAllocResult {
@@ -639,7 +641,7 @@ func (b *B) Run(name string, f func(b *B)) bool {
 		atomic.StoreInt32(&sub.hasSub, 1)
 	}
 
-	if b.chatty {
+	if b.chatty != nil {
 		labelsOnce.Do(func() {
 			fmt.Printf("goos: %s\n", runtime.GOOS)
 			fmt.Printf("goarch: %s\n", runtime.GOARCH)

src/testing/sub_test.go

@@ -483,10 +483,12 @@ func TestTRun(t *T) {
 					signal: make(chan bool),
 					name:   "Test",
 					w:      buf,
-					chatty: tc.chatty,
 				},
 				context: ctx,
 			}
+			if tc.chatty {
+				root.chatty = newChattyPrinter(root.w)
+			}
 			ok := root.Run(tc.desc, tc.f)
 			ctx.release()
 
@@ -665,11 +667,13 @@ func TestBRun(t *T) {
 					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},
 			}
+			if tc.chatty {
+				root.chatty = newChattyPrinter(root.w)
+			}
 			root.runN(1)
 			if ok != !tc.failed {
 				t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, !tc.failed)
@@ -741,9 +745,13 @@ func TestParallelSub(t *T) {
 	}
 }
 
-type funcWriter func([]byte) (int, error)
+type funcWriter struct {
+	write func([]byte) (int, error)
+}
 
-func (fw funcWriter) Write(b []byte) (int, error) { return fw(b) }
+func (fw *funcWriter) Write(b []byte) (int, error) {
+	return fw.write(b)
+}
 
 func TestRacyOutput(t *T) {
 	var runs int32  // The number of running Writes
@@ -761,9 +769,10 @@ func TestRacyOutput(t *T) {
 
 	var wg sync.WaitGroup
 	root := &T{
-		common:  common{w: funcWriter(raceDetector), chatty: true},
+		common:  common{w: &funcWriter{raceDetector}},
 		context: newTestContext(1, newMatcher(regexp.MatchString, "", "")),
 	}
+	root.chatty = newChattyPrinter(root.w)
 	root.Run("", func(t *T) {
 		for i := 0; i < 100; i++ {
 			wg.Add(1)

src/testing/testing.go

@@ -327,7 +327,6 @@ var (
 	cpuListStr           *string
 	parallel             *int
 	testlog              *string
-	printer              *testPrinter
 
 	haveExamples bool // are there examples?
 
@@ -337,55 +336,45 @@ var (
 	numFailed uint32 // number of test failures
 )
 
-type testPrinter struct {
-	chatty bool
-
+type chattyPrinter struct {
+	w          io.Writer
 	lastNameMu sync.Mutex // guards lastName
 	lastName   string     // last printed test name in chatty mode
 }
 
-func newTestPrinter(chatty bool) *testPrinter {
-	return &testPrinter{
-		chatty: chatty,
-	}
+func newChattyPrinter(w io.Writer) *chattyPrinter {
+	return &chattyPrinter{w: w}
 }
 
-func (p *testPrinter) Print(testName, out string) {
-	p.Fprint(os.Stdout, testName, out)
+// Updatef prints a message about the status of the named test to w.
+//
+// The formatted message must include the test name itself.
+func (p *chattyPrinter) Updatef(testName, format string, args ...interface{}) {
+	p.lastNameMu.Lock()
+	defer p.lastNameMu.Unlock()
+
+	// Since the message already implies an association with a specific new test,
+	// we don't need to check what the old test name was or log an extra CONT line
+	// for it. (We're updating it anyway, and the current message already includes
+	// the test name.)
+	p.lastName = testName
+	fmt.Fprintf(p.w, format, args...)
 }
 
-func (p *testPrinter) Fprint(w io.Writer, testName, out string) {
+// Printf prints a message, generated by the named test, that does not
+// necessarily mention that tests's name itself.
+func (p *chattyPrinter) Printf(testName, format string, args ...interface{}) {
 	p.lastNameMu.Lock()
 	defer p.lastNameMu.Unlock()
 
-	if !p.chatty ||
-		strings.HasPrefix(out, "--- PASS: ") ||
-		strings.HasPrefix(out, "--- FAIL: ") ||
-		strings.HasPrefix(out, "--- SKIP: ") ||
-		strings.HasPrefix(out, "=== RUN   ") ||
-		strings.HasPrefix(out, "=== CONT  ") ||
-		strings.HasPrefix(out, "=== PAUSE ") {
-		// If we're buffering test output (!p.chatty), we don't really care which
-		// test is emitting which line so long as they are serialized.
-		//
-		// If the message already implies an association with a specific new test,
-		// we don't need to check what the old test name was or log an extra CONT
-		// line for it. (We're updating it anyway, and the current message already
-		// includes the test name.)
-		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)
+		fmt.Fprintf(p.w, "=== CONT  %s\n", testName)
 		p.lastName = testName
 	}
-	fmt.Fprint(w, out)
+
+	fmt.Fprintf(p.w, format, args...)
 }
 
 // The maximum number of stack frames to go through when skipping helper functions for
@@ -407,12 +396,12 @@ type common struct {
 	cleanupName string              // Name of the cleanup function.
 	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.
+	chatty     *chattyPrinter // A copy of chattyPrinter, if the chatty flag is set.
+	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.
 
 	parent   *common
 	level    int       // Nesting depth of test or benchmark.
@@ -574,12 +563,31 @@ func (c *common) flushToParent(testName, format string, args ...interface{}) {
 	p.mu.Lock()
 	defer p.mu.Unlock()
 
-	printer.Fprint(p.w, testName, fmt.Sprintf(format, args...))
-
 	c.mu.Lock()
 	defer c.mu.Unlock()
-	io.Copy(p.w, bytes.NewReader(c.output))
-	c.output = c.output[:0]
+
+	if len(c.output) > 0 {
+		format += "%s"
+		args = append(args[:len(args):len(args)], c.output)
+		c.output = c.output[:0] // but why?
+	}
+
+	if c.chatty != nil && p.w == c.chatty.w {
+		// We're flushing to the actual output, so track that this output is
+		// associated with a specific test (and, specifically, that the next output
+		// is *not* associated with that test).
+		//
+		// Moreover, if c.output is non-empty it is important that this write be
+		// atomic with respect to the output of other tests, so that we don't end up
+		// with confusing '=== CONT' lines in the middle of our '--- PASS' block.
+		// Neither humans nor cmd/test2json can parse those easily.
+		// (See https://golang.org/issue/40771.)
+		c.chatty.Updatef(testName, format, args...)
+	} else {
+		// We're flushing to the output buffer of the parent test, which will
+		// itself follow a test-name header when it is finally flushed to stdout.
+		fmt.Fprintf(p.w, format, args...)
+	}
 }
 
 type indenter struct {
@@ -748,13 +756,13 @@ func (c *common) logDepth(s string, depth int) {
 		}
 		panic("Log in goroutine after " + c.name + " has completed")
 	} else {
-		if c.chatty {
+		if c.chatty != nil {
 			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))
+				c.chatty.Printf(c.name, "%s", c.decorate(s, depth+1))
 			}
 
 			return
@@ -1003,34 +1011,22 @@ func (t *T) Parallel() {
 	t.parent.sub = append(t.parent.sub, t)
 	t.raceErrors += race.Errors()
 
-	if t.chatty {
-		// Print directly to root's io.Writer so there is no delay.
-		root := t.parent
-		for ; root.parent != nil; root = root.parent {
-		}
-		root.mu.Lock()
+	if t.chatty != nil {
 		// Unfortunately, even though PAUSE indicates that the named test is *no
 		// longer* running, cmd/test2json interprets it as changing the active test
 		// for the purpose of log parsing. We could fix cmd/test2json, but that
 		// won't fix existing deployments of third-party tools that already shell
 		// out to older builds of cmd/test2json — so merely fixing cmd/test2json
 		// isn't enough for now.
-		printer.Fprint(root.w, t.name, fmt.Sprintf("=== PAUSE %s\n", t.name))
-		root.mu.Unlock()
+		t.chatty.Updatef(t.name, "=== PAUSE %s\n", t.name)
 	}
 
 	t.signal <- true   // Release calling test.
 	<-t.parent.barrier // Wait for the parent test to complete.
 	t.context.waitParallel()
 
-	if t.chatty {
-		// Print directly to root's io.Writer so there is no delay.
-		root := t.parent
-		for ; root.parent != nil; root = root.parent {
-		}
-		root.mu.Lock()
-		printer.Fprint(root.w, t.name, fmt.Sprintf("=== CONT  %s\n", t.name))
-		root.mu.Unlock()
+	if t.chatty != nil {
+		t.chatty.Updatef(t.name, "=== CONT  %s\n", t.name)
 	}
 
 	t.start = time.Now()
@@ -1181,14 +1177,8 @@ func (t *T) Run(name string, f func(t *T)) bool {
 	}
 	t.w = indenter{&t.common}
 
-	if t.chatty {
-		// Print directly to root's io.Writer so there is no delay.
-		root := t.parent
-		for ; root.parent != nil; root = root.parent {
-		}
-		root.mu.Lock()
-		printer.Fprint(root.w, t.name, fmt.Sprintf("=== RUN   %s\n", t.name))
-		root.mu.Unlock()
+	if t.chatty != nil {
+		t.chatty.Updatef(t.name, "=== RUN   %s\n", t.name)
 	}
 	// Instead of reducing the running count of this test before calling the
 	// tRunner and increasing it afterwards, we rely on tRunner keeping the
@@ -1355,8 +1345,6 @@ 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()
@@ -1401,7 +1389,7 @@ func (t *T) report() {
 	format := "--- %s: %s (%s)\n"
 	if t.Failed() {
 		t.flushToParent(t.name, format, "FAIL", t.name, dstr)
-	} else if t.chatty {
+	} else if t.chatty != nil {
 		if t.Skipped() {
 			t.flushToParent(t.name, format, "SKIP", t.name, dstr)
 		} else {
@@ -1462,10 +1450,12 @@ func runTests(matchString func(pat, str string) (bool, error), tests []InternalT
 					signal:  make(chan bool),
 					barrier: make(chan bool),
 					w:       os.Stdout,
-					chatty:  *chatty,
 				},
 				context: ctx,
 			}
+			if Verbose() {
+				t.chatty = newChattyPrinter(t.w)
+			}
 			tRunner(t, func(t *T) {
 				for _, test := range tests {
 					t.Run(test.Name, test.F)