testing: add a new output writer and use it in t.Log

src/testing/benchmark.go

@@ -675,6 +675,7 @@ func (s *benchState) processBench(b *B) {
 					benchFunc: b.benchFunc,
 					benchTime: b.benchTime,
 				}
+				b.o = &outputWriter{&b.common, nil}
 				b.run1()
 			}
 			r := b.doBench()
@@ -751,6 +752,7 @@ func (b *B) Run(name string, f func(b *B)) bool {
 		benchTime:  b.benchTime,
 		bstate:     b.bstate,
 	}
+	sub.o = &outputWriter{&sub.common, nil}
 	if partial {
 		// Partial name match, like -bench=X/Y matching BenchmarkX.
 		// Only process sub-benchmarks, if any.
@@ -927,6 +929,7 @@ func Benchmark(f func(b *B)) BenchmarkResult {
 		benchFunc: f,
 		benchTime: benchTime,
 	}
+	b.o = &outputWriter{&b.common, nil}
 	if b.run1() {
 		b.run()
 	}

src/testing/fuzz.go

@@ -320,6 +320,7 @@ func (f *F) Fuzz(ff any) {
 			t.parent.w = captureOut
 		}
 		t.w = indenter{&t.common}
+		t.o = &outputWriter{&t.common, nil}
 		if t.chatty != nil {
 			t.chatty.Updatef(t.name, "=== RUN   %s\n", t.name)
 		}
@@ -529,6 +530,7 @@ func runFuzzTests(deps testDeps, fuzzTests []InternalFuzzTarget, deadline time.T
 					fstate: fstate,
 				}
 				f.w = indenter{&f.common}
+				f.o = &outputWriter{&f.common, nil}
 				if f.chatty != nil {
 					f.chatty.Updatef(f.name, "=== RUN   %s\n", f.name)
 				}

src/testing/sub_test.go

@@ -831,6 +831,7 @@ func TestLogAfterComplete(t *T) {
 	tRunner(t1, func(t *T) {
 		t.Run("TestLateLog", func(t *T) {
 			go func() {
+				const l = "log after test"
 				defer close(c2)
 				defer func() {
 					p := recover()
@@ -843,14 +844,17 @@ func TestLogAfterComplete(t *T) {
 						c2 <- fmt.Sprintf("subtest panic with unexpected value %v", p)
 						return
 					}
-					const want = "Log in goroutine after TestLateLog has completed: log after test"
-					if !strings.Contains(s, want) {
-						c2 <- fmt.Sprintf("subtest panic %q does not contain %q", s, want)
+					const message = "Log in goroutine after TestLateLog has completed"
+					if !strings.Contains(s, message) {
+						c2 <- fmt.Sprintf("subtest panic %q does not contain %q", s, message)
+					}
+					if !strings.Contains(s, l) {
+						c2 <- fmt.Sprintf("subtest panic %q does not contain %q", s, l)
 					}
 				}()
 
 				<-c1
-				t.Log("log after test")
+				t.Log(l)
 			}()
 		})
 	})

src/testing/testing.go

@@ -626,6 +626,7 @@ type common struct {
 	mu          sync.RWMutex         // guards this group of fields
 	output      []byte               // Output generated by test or benchmark.
 	w           io.Writer            // For flushToParent.
+	o           io.Writer            // Writes output.
 	ran         bool                 // Test or benchmark (or one of its subtests) was executed.
 	failed      bool                 // Test or benchmark has failed.
 	skipped     bool                 // Test or benchmark has been skipped.
@@ -797,44 +798,6 @@ func (c *common) frameSkip(skip int) runtime.Frame {
 	return firstFrame
 }
 
-// decorate prefixes the string with the file and line of the call site
-// and inserts the final newline if needed and indentation spaces for formatting.
-// This function must be called with c.mu held.
-func (c *common) decorate(s string, skip int) string {
-	frame := c.frameSkip(skip)
-	file := frame.File
-	line := frame.Line
-	if file != "" {
-		if *fullPath {
-			// If relative path, truncate file name at last file name separator.
-		} else if index := strings.LastIndexAny(file, `/\`); index >= 0 {
-			file = file[index+1:]
-		}
-	} else {
-		file = "???"
-	}
-	if line == 0 {
-		line = 1
-	}
-	buf := new(strings.Builder)
-	// Every line is indented at least 4 spaces.
-	buf.WriteString("    ")
-	fmt.Fprintf(buf, "%s:%d: ", file, line)
-	lines := strings.Split(s, "\n")
-	if l := len(lines); l > 1 && lines[l-1] == "" {
-		lines = lines[:l-1]
-	}
-	for i, line := range lines {
-		if i > 0 {
-			// Second and subsequent lines are indented an additional 4 spaces.
-			buf.WriteString("\n        ")
-		}
-		buf.WriteString(line)
-	}
-	buf.WriteByte('\n')
-	return buf.String()
-}
-
 // flushToParent writes c.output to the parent after first writing the header
 // with the given format and arguments.
 func (c *common) flushToParent(testName, format string, args ...any) {
@@ -1041,40 +1004,123 @@ func (c *common) FailNow() {
 	runtime.Goexit()
 }
 
-// log generates the output. It's always at the same stack depth.
+// log generates the output. It is always at the same stack depth. log inserts
+// indentation and the final newline if necessary. It prefixes the string
+// with the file and line of the call site.
 func (c *common) log(s string) {
-	c.logDepth(s, 3) // logDepth + log + public function
+	if l := len(s); l > 0 && (string(s[l-1]) == "\n") {
+		s = s[:l-1]
+	}
+	// Second and subsequent lines are indented 4 spaces. This is in addition to
+	// the indentation provided by outputWriter.
+	s = strings.Replace(s, "\n", "\n    ", -1)
+	s += "\n"
+
+	// Prefix with the call site. It is located by skipping 3 functions:
+	// callSite + log + public function
+	s = c.callSite(3) + s
+	c.o.Write([]byte(s))
 }
 
-// logDepth generates the output at an arbitrary stack depth.
-func (c *common) logDepth(s string, depth int) {
+// callSite retrieves and formats the file and line of the call site.
+func (c *common) callSite(skip int) string {
 	c.mu.Lock()
 	defer c.mu.Unlock()
-	if c.done {
+
+	frame := c.frameSkip(skip)
+	file := frame.File
+	line := frame.Line
+	if file != "" {
+		if *fullPath {
+			// If relative path, truncate file name at last file name separator.
+		} else if index := strings.LastIndexAny(file, `/\`); index >= 0 {
+			file = file[index+1:]
+		}
+	} else {
+		file = "???"
+	}
+	if line == 0 {
+		line = 1
+	}
+
+	return fmt.Sprintf("%s:%d: ", file, line)
+}
+
+// newOutputWriter initialises a new outputWriter.
+func (c *common) newOutputWriter() io.Writer {
+	return &outputWriter{c, nil}
+}
+
+// outputWriter buffers, formats and writes input.
+type outputWriter struct {
+	c *common
+	b []byte // Stores incomplete input between writes.
+}
+
+// Write generates the output. It inserts indentation spaces for formatting and
+// stores input for later if it is not terminated by a newline.
+func (o *outputWriter) Write(p []byte) (int, error) {
+	s := string(append(o.b, p...))
+
+	o.c.mu.Lock()
+	defer o.c.mu.Unlock()
+
+	lines := strings.Split(s, "\n")
+
+	for i, line := range lines {
+		l := len(lines)
+		// If the last line is not empty, store it in the buffer.
+		if i == (l-1) && line != "" {
+			o.b = []byte(line)
+			if i > 0 {
+				o.writeLine("\n", p)
+			}
+			break
+		}
+
+		buf := new(strings.Builder)
+		// Add back newlines.
+		if i != 0 {
+			buf.WriteString("\n")
+		}
+		// All lines are indented 4 spaces except the final one, which must be
+		// empty otherwise the loop would have terminated earlier.
+		if i != l-1 {
+			buf.WriteString("    ")
+		}
+		buf.WriteString(line)
+
+		o.writeLine(buf.String(), p)
+	}
+	return len(p), nil
+}
+
+// writeLine generates the output for a given line.
+func (o *outputWriter) writeLine(s string, p []byte) {
+	if o.c.done {
 		// This test has already finished. Try and log this message
 		// with our parent. If we don't have a parent, panic.
-		for parent := c.parent; parent != nil; parent = parent.parent {
+		for parent := o.c.parent; parent != nil; parent = parent.parent {
 			parent.mu.Lock()
 			defer parent.mu.Unlock()
 			if !parent.done {
-				parent.output = append(parent.output, parent.decorate(s, depth+1)...)
+				parent.output = append(parent.output, s...)
 				return
 			}
 		}
-		panic("Log in goroutine after " + c.name + " has completed: " + s)
+		panic("Log in goroutine after " + o.c.name + " has completed: " + string(p))
 	} else {
-		if c.chatty != nil {
-			if c.bench {
+		if o.c.chatty != nil {
+			if o.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))
+				fmt.Print(s)
 			} else {
-				c.chatty.Printf(c.name, "%s", c.decorate(s, depth+1))
+				o.c.chatty.Printf(o.c.name, "%s", s)
 			}
-
-			return
+		} else {
+			o.c.output = append(o.c.output, s...)
 		}
-		c.output = append(c.output, c.decorate(s, depth+1)...)
 	}
 }
 
@@ -1837,6 +1883,7 @@ func (t *T) Run(name string, f func(t *T)) bool {
 		tstate: t.tstate,
 	}
 	t.w = indenter{&t.common}
+	t.o = &outputWriter{&t.common, nil}
 
 	if t.chatty != nil {
 		t.chatty.Updatef(t.name, "=== RUN   %s\n", t.name)