From 8d189f188e225e4919b34c0c097e75dfda255949 Mon Sep 17 00:00:00 2001 From: suntala Date: Mon, 12 May 2025 19:23:41 +0000 Subject: [PATCH] testing: add Output Output is a method on T, B and F. It provides an io.Writer that writes to the same test output stream as TB.Log. The new output writer is used to refactor the implementation of Log. It maintains the formatting provided by Log while making call site information optional. Additionally, it provides buffering of log messages. Co-authored-by: Aleks Fazlieva Fixes #59928. Change-Id: I29090b3d4f61f7334388b373ec18750d5637aafa GitHub-Last-Rev: 18af0e15262494f2074d545a6042b079d62301a2 GitHub-Pull-Request: golang/go#71575 Reviewed-on: https://go-review.googlesource.com/c/go/+/646956 Reviewed-by: Arati Auto-Submit: Jonathan Amsterdam Reviewed-by: Jonathan Amsterdam LUCI-TryBot-Result: Go LUCI Reviewed-by: Michael Knyszek --- api/next/59928.txt | 3 + doc/next/6-stdlib/99-minor/testing/59928.md | 4 + src/testing/benchmark.go | 3 + src/testing/fuzz.go | 2 + src/testing/panic_test.go | 19 ++ src/testing/sub_test.go | 263 +++++++++++++++++++- src/testing/testing.go | 214 +++++++++++----- 7 files changed, 443 insertions(+), 65 deletions(-) create mode 100644 api/next/59928.txt create mode 100644 doc/next/6-stdlib/99-minor/testing/59928.md diff --git a/api/next/59928.txt b/api/next/59928.txt new file mode 100644 index 0000000000..375c7c0e90 --- /dev/null +++ b/api/next/59928.txt @@ -0,0 +1,3 @@ +pkg testing, method (*B) Output() io.Writer #59928 +pkg testing, method (*F) Output() io.Writer #59928 +pkg testing, method (*T) Output() io.Writer #59928 diff --git a/doc/next/6-stdlib/99-minor/testing/59928.md b/doc/next/6-stdlib/99-minor/testing/59928.md new file mode 100644 index 0000000000..6879a10d63 --- /dev/null +++ b/doc/next/6-stdlib/99-minor/testing/59928.md @@ -0,0 +1,4 @@ + + +The new [Output] method of [testing.T], [testing.B] and [testing.F] provides a Writer +that writes to the same test output stream as [TB.Log], but omits the file and line number. diff --git a/src/testing/benchmark.go b/src/testing/benchmark.go index 1a27aa23fc..cedd75ea66 100644 --- a/src/testing/benchmark.go +++ b/src/testing/benchmark.go @@ -755,6 +755,7 @@ func (s *benchState) processBench(b *B) { benchFunc: b.benchFunc, benchTime: b.benchTime, } + b.setOutputWriter() b.run1() } r := b.doBench() @@ -831,6 +832,7 @@ func (b *B) Run(name string, f func(b *B)) bool { benchTime: b.benchTime, bstate: b.bstate, } + sub.setOutputWriter() if partial { // Partial name match, like -bench=X/Y matching BenchmarkX. // Only process sub-benchmarks, if any. @@ -1007,6 +1009,7 @@ func Benchmark(f func(b *B)) BenchmarkResult { benchFunc: f, benchTime: benchTime, } + b.setOutputWriter() if b.run1() { b.run() } diff --git a/src/testing/fuzz.go b/src/testing/fuzz.go index 0e04aff6e7..f1b5242ed6 100644 --- a/src/testing/fuzz.go +++ b/src/testing/fuzz.go @@ -320,6 +320,7 @@ func (f *F) Fuzz(ff any) { t.parent.w = captureOut } t.w = indenter{&t.common} + t.setOutputWriter() 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.setOutputWriter() if f.chatty != nil { f.chatty.Updatef(f.name, "=== RUN %s\n", f.name) } diff --git a/src/testing/panic_test.go b/src/testing/panic_test.go index 1c42f9f8dd..fc84175ee6 100644 --- a/src/testing/panic_test.go +++ b/src/testing/panic_test.go @@ -34,6 +34,7 @@ func TestPanic(t *testing.T) { want: ` --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper `, }, { desc: "subtest panics", @@ -41,8 +42,10 @@ func TestPanic(t *testing.T) { want: ` --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper --- FAIL: TestPanicHelper/1 (N.NNs) panic_test.go:NNN: TestPanicHelper/1 + TestPanicHelper/1 `, }, { desc: "subtest panics with cleanup", @@ -53,8 +56,10 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper --- FAIL: TestPanicHelper/1 (N.NNs) panic_test.go:NNN: TestPanicHelper/1 + TestPanicHelper/1 `, }, { desc: "subtest panics with outer cleanup panic", @@ -65,6 +70,7 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper `, }, { desc: "subtest panics with middle cleanup panic", @@ -75,8 +81,10 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper --- FAIL: TestPanicHelper/1 (N.NNs) panic_test.go:NNN: TestPanicHelper/1 + TestPanicHelper/1 `, }, { desc: "subtest panics with inner cleanup panic", @@ -87,8 +95,10 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper --- FAIL: TestPanicHelper/1 (N.NNs) panic_test.go:NNN: TestPanicHelper/1 + TestPanicHelper/1 `, }, { desc: "parallel subtest panics with cleanup", @@ -99,8 +109,10 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper --- FAIL: TestPanicHelper/1 (N.NNs) panic_test.go:NNN: TestPanicHelper/1 + TestPanicHelper/1 `, }, { desc: "parallel subtest panics with outer cleanup panic", @@ -111,6 +123,7 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper `, }, { desc: "parallel subtest panics with middle cleanup panic", @@ -121,8 +134,10 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper --- FAIL: TestPanicHelper/1 (N.NNs) panic_test.go:NNN: TestPanicHelper/1 + TestPanicHelper/1 `, }, { desc: "parallel subtest panics with inner cleanup panic", @@ -133,8 +148,10 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper + TestPanicHelper --- FAIL: TestPanicHelper/1 (N.NNs) panic_test.go:NNN: TestPanicHelper/1 + TestPanicHelper/1 `, }} for _, tc := range testCases { @@ -165,6 +182,7 @@ func TestPanicHelper(t *testing.T) { return } t.Log(t.Name()) + t.Output().Write([]byte(t.Name())) if t.Name() == *testPanicTest { panic("panic") } @@ -195,6 +213,7 @@ func TestPanicHelper(t *testing.T) { t.Parallel() } t.Log(t.Name()) + t.Output().Write([]byte(t.Name())) if chosen { if *testPanicCleanup { t.Cleanup(func() { diff --git a/src/testing/sub_test.go b/src/testing/sub_test.go index 82ec5809e5..1a6cfed594 100644 --- a/src/testing/sub_test.go +++ b/src/testing/sub_test.go @@ -503,6 +503,100 @@ func TestTRun(t *T) { t2.FailNow() }) }, + }, { + desc: "buffered output gets flushed at test end", + ok: false, + output: ` +--- FAIL: buffered output gets flushed at test end (0.00s) + --- FAIL: buffered output gets flushed at test end/#00 (0.00s) + a + b`, + f: func(t *T) { + t.Run("", func(t *T) { + o := t.Output() + o.Write([]byte("a\n")) + o.Write([]byte("b")) + t.Fail() + }) + }, + }, { + desc: "output with chatty", + ok: true, + chatty: true, + output: ` +=== RUN output with chatty +=== RUN output with chatty/#00 + a + b +--- PASS: output with chatty (0.00s) + --- PASS: output with chatty/#00 (0.00s)`, + f: func(t *T) { + t.Run("", func(t *T) { + o := t.Output() + o.Write([]byte("a\n")) + o.Write([]byte("b")) + }) + }, + }, { + desc: "output with chatty and json", + ok: true, + chatty: true, + json: true, + output: ` +^V=== RUN output with chatty and json +^V=== RUN output with chatty and json/#00 + a + b +^V--- PASS: output with chatty and json/#00 (0.00s) +^V=== NAME output with chatty and json +^V--- PASS: output with chatty and json (0.00s) +^V=== NAME +`, + f: func(t *T) { + t.Run("", func(t *T) { + o := t.Output() + o.Write([]byte("a\n")) + o.Write([]byte("b")) + }) + }, + }, { + desc: "output in finished sub test outputs to parent", + ok: false, + output: ` + --- FAIL: output in finished sub test outputs to parent (N.NNs) + message2 + message1 + sub_test.go:NNN: error`, + f: func(t *T) { + ch := make(chan bool) + t.Run("sub", func(t2 *T) { + go func() { + <-ch + t2.Output().Write([]byte("message1\n")) + ch <- true + }() + }) + t.Output().Write([]byte("message2\n")) + ch <- true + <-ch + t.Errorf("error") + }, + }, { + desc: "newline between buffered log and log", + ok: false, + output: ` +--- FAIL: newline between buffered log and log (0.00s) + --- FAIL: newline between buffered log and log/#00 (0.00s) + buffered message + sub_test.go:NNN: log`, + f: func(t *T) { + t.Run("", func(t *T) { + o := t.Output() + o.Write([]byte("buffered message")) + t.Log("log") + t.Fail() + }) + }, }} for _, tc := range testCases { t.Run(tc.desc, func(t *T) { @@ -840,7 +934,7 @@ func TestLogAfterComplete(t *T) { } s, ok := p.(string) if !ok { - c2 <- fmt.Sprintf("subtest panic with unexpected value %v", p) + c2 <- fmt.Sprintf("subtest panic with unexpected value %v of type %T", p, p) return } const want = "Log in goroutine after TestLateLog has completed: log after test" @@ -989,3 +1083,170 @@ func TestNestedCleanup(t *T) { t.Errorf("unexpected cleanup count: got %d want 3", ranCleanup) } } + +// TestOutput checks that log messages are written, +// formatted and buffered as expected by Output. It +// checks both the chatty and non-chatty cases. +func TestOutput(t *T) { + tstate := newTestState(1, allMatcher()) + root := &T{ + tstate: tstate, + } + root.setOutputWriter() + o := root.Output() + + // Chatty case + tstateChatty := newTestState(1, allMatcher()) + bufChatty := &strings.Builder{} + rootChatty := &T{ + common: common{ + w: bufChatty, + }, + tstate: tstateChatty, + } + rootChatty.setOutputWriter() + rootChatty.chatty = newChattyPrinter(rootChatty.w) + oChatty := rootChatty.Output() + + testCases := []struct { + in string + out string + buf string + }{{ + in: "a", + out: "", + buf: "a", + }, { + in: "b", + out: "", + buf: "ab", + }, { + in: "\n", + out: " ab\n", + buf: "", + }, { + in: "\nc", + out: " ab\n \n", + buf: "c", + }, { + in: "d", + out: " ab\n \n", + buf: "cd", + }} + for _, tc := range testCases { + o.Write([]byte(tc.in)) + if string(root.output) != tc.out { + t.Errorf("output:\ngot:\n%s\nwant:\n%s", root.output, tc.out) + } + if string(root.o.partial) != tc.buf { + t.Errorf("buffer:\ngot:\n%s\nwant:\n%s", root.o.partial, tc.buf) + } + + // Chatty case + oChatty.Write([]byte(tc.in)) + if got := bufChatty.String(); got != tc.out { + t.Errorf("output:\ngot:\n%s\nwant:\n%s", got, tc.out) + } + } +} + +// TestOutputAfterComplete ensures that Output panics +// if called after a test function returns. +func TestOutputAfterComplete(t *T) { + tstate := newTestState(1, allMatcher()) + var buf bytes.Buffer + t1 := &T{ + common: common{ + // Use a buffered channel so that tRunner can write + // to it although nothing is reading from it. + signal: make(chan bool, 1), + w: &buf, + }, + tstate: tstate, + } + + c1 := make(chan bool) + c2 := make(chan string) + tRunner(t1, func(t *T) { + t.Run("TestLateOutput", func(t *T) { + go func() { + defer close(c2) + defer func() { + p := recover() + if p == nil { + c2 <- "subtest did not panic" + return + } + s, ok := p.(string) + if !ok { + c2 <- fmt.Sprintf("subtest panic with unexpected value %v of type %T", p, p) + return + } + const want = "Output called after TestLateOutput has completed" + if !strings.Contains(s, want) { + c2 <- fmt.Sprintf("subtest panic %q does not contain %q", s, want) + } + }() + + <-c1 + t.Output() + }() + }) + }) + close(c1) + + if s := <-c2; s != "" { + t.Error(s) + } +} + +// TestOutputWriteAfterComplete ensures that Write panics +// if called on t.Output() of a finished test t. +func TestOutputWriteAfterComplete(t *T) { + tstate := newTestState(1, allMatcher()) + var buf bytes.Buffer + t1 := &T{ + common: common{ + // Use a buffered channel so that tRunner can write + // to it although nothing is reading from it. + signal: make(chan bool, 1), + w: &buf, + }, + tstate: tstate, + } + + c1 := make(chan bool) + c2 := make(chan string) + tRunner(t1, func(t *T) { + t.Run("TestLateWrite", func(t *T) { + o := t.Output() + go func() { + defer close(c2) + defer func() { + p := recover() + if p == nil { + c2 <- "subtest did not panic" + return + } + s, ok := p.(string) + if !ok { + c2 <- fmt.Sprintf("subtest panic with unexpected value %v of type %T", p, p) + return + } + const want = "Write called after TestLateWrite has completed" + if !strings.Contains(s, want) { + c2 <- fmt.Sprintf("subtest panic %q does not contain %q", s, want) + } + }() + + <-c1 + o.Write([]byte("write after test")) + }() + }) + }) + close(c1) + + if s := <-c2; s != "" { + t.Error(s) + } +} diff --git a/src/testing/testing.go b/src/testing/testing.go index d50abea32f..efbcd59dc0 100644 --- a/src/testing/testing.go +++ b/src/testing/testing.go @@ -631,6 +631,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 *outputWriter // 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. @@ -799,44 +800,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) { @@ -882,6 +845,8 @@ type indenter struct { c *common } +const indent = " " + func (w indenter) Write(b []byte) (n int, err error) { n = len(b) for len(b) > 0 { @@ -898,7 +863,6 @@ func (w indenter) Write(b []byte) (n int, err error) { w.c.output = append(w.c.output, marker) line = line[1:] } - const indent = " " w.c.output = append(w.c.output, indent...) w.c.output = append(w.c.output, line...) b = b[end:] @@ -1043,41 +1007,156 @@ 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 + s = strings.TrimSuffix(s, "\n") + + // Second and subsequent lines are indented 4 spaces. This is in addition to + // the indentation provided by outputWriter. + s = strings.ReplaceAll(s, "\n", "\n"+indent) + s += "\n" + + n := c.destination() + if n == nil { + // The test and all its parents are done. The log cannot be output. + panic("Log in goroutine after " + c.name + " has completed: " + s) + } + + // Prefix with the call site. It is located by skipping 3 functions: + // callSite + log + public function + s = n.callSite(3) + s + + // Output buffered logs. + n.flushPartial() + + n.o.Write([]byte(s)) } -// logDepth generates the output at an arbitrary stack depth. -func (c *common) logDepth(s string, depth int) { +// destination selects the test to which output should be appended. It returns the +// test if it is incomplete. Otherwise, it finds its closest incomplete parent. +func (c *common) destination() *common { c.mu.Lock() defer c.mu.Unlock() - if 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 { - parent.mu.Lock() - defer parent.mu.Unlock() - if !parent.done { - parent.output = append(parent.output, parent.decorate(s, depth+1)...) - return - } + + if !c.done { + return c + } + for parent := c.parent; parent != nil; parent = parent.parent { + parent.mu.Lock() + defer parent.mu.Unlock() + if !parent.done { + return parent + } + } + return nil +} + +// 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() + + 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 { + file = filepath.Base(file) } - panic("Log in goroutine after " + c.name + " has completed: " + s) } else { - 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 { - c.chatty.Printf(c.name, "%s", c.decorate(s, depth+1)) - } + file = "???" + } + if line == 0 { + line = 1 + } - return + return fmt.Sprintf("%s:%d: ", file, line) +} + +// flushPartial checks the buffer for partial logs and outputs them. +func (c *common) flushPartial() { + partial := func() bool { + c.mu.Lock() + defer c.mu.Unlock() + return (c.o != nil) && (len(c.o.partial) > 0) + } + + if partial() { + c.o.Write([]byte("\n")) + } +} + +// Output returns a Writer that writes to the same test output stream as TB.Log. +// The output is indented like TB.Log lines, but Output does not +// add source locations or newlines. The output is internally line +// buffered, and a call to TB.Log or the end of the test will implicitly +// flush the buffer, followed by a newline. After a test function and all its +// parents return, neither Output nor the Write method may be called. +func (c *common) Output() io.Writer { + c.checkFuzzFn("Output") + n := c.destination() + if n == nil { + panic("Output called after " + c.name + " has completed") + } + return n.o +} + +// setOutputWriter initializes an outputWriter and sets it as a common field. +func (c *common) setOutputWriter() { + c.o = &outputWriter{c: c} +} + +// outputWriter buffers, formats and writes log messages. +type outputWriter struct { + c *common + partial []byte // incomplete ('\n'-free) suffix of last Write +} + +// Write writes a log message to the test's output stream, properly formatted and +// indented. It may not be called after a test function and all its parents return. +func (o *outputWriter) Write(p []byte) (int, error) { + if o.c.destination() == nil { + panic("Write called after " + o.c.name + " has completed") + } + + o.c.mu.Lock() + defer o.c.mu.Unlock() + + // The last element is a partial line. + lines := bytes.SplitAfter(p, []byte("\n")) + last := len(lines) - 1 // Inv: 0 <= last + for i, line := range lines[:last] { + // Emit partial line from previous call. + if i == 0 && len(o.partial) > 0 { + line = slices.Concat(o.partial, line) + o.partial = o.partial[:0] + } + o.writeLine(line) + } + // Save partial line for next call. + o.partial = append(o.partial, lines[last]...) + + return len(p), nil +} + +// writeLine generates the output for a given line. +func (o *outputWriter) writeLine(b []byte) { + if !o.c.done && (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.Printf("%s%s", indent, b) + } else { + o.c.chatty.Printf(o.c.name, "%s%s", indent, b) } - c.output = append(c.output, c.decorate(s, depth+1)...) + return } + o.c.output = append(o.c.output, indent...) + o.c.output = append(o.c.output, b...) } // Log formats its arguments using default formatting, analogous to [fmt.Println], @@ -1739,6 +1818,8 @@ func tRunner(t *T, fn func(t *T)) { root.duration += highPrecisionTimeSince(root.start) d := root.duration root.mu.Unlock() + // Output buffered logs. + root.flushPartial() 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) @@ -1786,6 +1867,10 @@ func tRunner(t *T, fn func(t *T)) { // test. See comment in Run method. t.tstate.release() } + // Output buffered logs. + for root := &t.common; root.parent != nil; root = root.parent { + root.flushPartial() + } t.report() // Report after all subtests have finished. // Do not lock t.done to allow race detector to detect race in case @@ -1851,6 +1936,7 @@ func (t *T) Run(name string, f func(t *T)) bool { tstate: t.tstate, } t.w = indenter{&t.common} + t.setOutputWriter() if t.chatty != nil { t.chatty.Updatef(t.name, "=== RUN %s\n", t.name) -- 2.51.0