diff --git a/api/next/59928.txt b/api/next/59928.txt new file mode 100644 index 00000000000000..375c7c0e90c208 --- /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 00000000000000..6879a10d6342cc --- /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 1a27aa23fcd47a..cedd75ea6699a9 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 0e04aff6e7baf5..c07d6a06048249 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) } @@ -614,6 +616,7 @@ func runFuzzing(deps testDeps, fuzzTests []InternalFuzzTarget) (ok bool) { tstate: tstate, } 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 1c42f9f8dd8b87..fc84175ee6f0dd 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 82ec5809e532be..1a6cfed594980e 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 d50abea32f2d3d..efbcd59dc09564 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)