From: Jonathan Amsterdam Date: Tue, 13 May 2025 18:50:58 +0000 (-0700) Subject: Revert "testing: add Output" X-Git-Tag: go1.25rc1~284 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=afd6b0bc663cf49e74200729da91785219d28b53;p=gostls13.git Revert "testing: add Output" This reverts commit 8d189f188e225e4919b34c0c097e75dfda255949. Reason for revert: failing test Change-Id: I951087eaef7818697acf87e3206003bcc8a81ee2 Reviewed-on: https://go-review.googlesource.com/c/go/+/672335 LUCI-TryBot-Result: Go LUCI Reviewed-by: Jonathan Amsterdam Auto-Submit: Michael Knyszek Reviewed-by: Michael Knyszek --- diff --git a/api/next/59928.txt b/api/next/59928.txt deleted file mode 100644 index 375c7c0e90..0000000000 --- a/api/next/59928.txt +++ /dev/null @@ -1,3 +0,0 @@ -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 deleted file mode 100644 index 6879a10d63..0000000000 --- a/doc/next/6-stdlib/99-minor/testing/59928.md +++ /dev/null @@ -1,4 +0,0 @@ - - -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 cedd75ea66..1a27aa23fc 100644 --- a/src/testing/benchmark.go +++ b/src/testing/benchmark.go @@ -755,7 +755,6 @@ func (s *benchState) processBench(b *B) { benchFunc: b.benchFunc, benchTime: b.benchTime, } - b.setOutputWriter() b.run1() } r := b.doBench() @@ -832,7 +831,6 @@ 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. @@ -1009,7 +1007,6 @@ 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 f1b5242ed6..0e04aff6e7 100644 --- a/src/testing/fuzz.go +++ b/src/testing/fuzz.go @@ -320,7 +320,6 @@ 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) } @@ -530,7 +529,6 @@ 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 fc84175ee6..1c42f9f8dd 100644 --- a/src/testing/panic_test.go +++ b/src/testing/panic_test.go @@ -34,7 +34,6 @@ func TestPanic(t *testing.T) { want: ` --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper - TestPanicHelper `, }, { desc: "subtest panics", @@ -42,10 +41,8 @@ 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", @@ -56,10 +53,8 @@ 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", @@ -70,7 +65,6 @@ ran middle cleanup 1 ran outer cleanup --- FAIL: TestPanicHelper (N.NNs) panic_test.go:NNN: TestPanicHelper - TestPanicHelper `, }, { desc: "subtest panics with middle cleanup panic", @@ -81,10 +75,8 @@ 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", @@ -95,10 +87,8 @@ 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", @@ -109,10 +99,8 @@ 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", @@ -123,7 +111,6 @@ 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", @@ -134,10 +121,8 @@ 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", @@ -148,10 +133,8 @@ 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 { @@ -182,7 +165,6 @@ func TestPanicHelper(t *testing.T) { return } t.Log(t.Name()) - t.Output().Write([]byte(t.Name())) if t.Name() == *testPanicTest { panic("panic") } @@ -213,7 +195,6 @@ 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 1a6cfed594..82ec5809e5 100644 --- a/src/testing/sub_test.go +++ b/src/testing/sub_test.go @@ -503,100 +503,6 @@ 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) { @@ -934,7 +840,7 @@ func TestLogAfterComplete(t *T) { } s, ok := p.(string) if !ok { - c2 <- fmt.Sprintf("subtest panic with unexpected value %v of type %T", p, p) + c2 <- fmt.Sprintf("subtest panic with unexpected value %v", p) return } const want = "Log in goroutine after TestLateLog has completed: log after test" @@ -1083,170 +989,3 @@ 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 efbcd59dc0..d50abea32f 100644 --- a/src/testing/testing.go +++ b/src/testing/testing.go @@ -631,7 +631,6 @@ 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. @@ -800,6 +799,44 @@ 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) { @@ -845,8 +882,6 @@ type indenter struct { c *common } -const indent = " " - func (w indenter) Write(b []byte) (n int, err error) { n = len(b) for len(b) > 0 { @@ -863,6 +898,7 @@ 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:] @@ -1007,156 +1043,41 @@ func (c *common) FailNow() { runtime.Goexit() } -// 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. +// log generates the output. It's always at the same stack depth. func (c *common) log(s string) { - 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)) -} - -// 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 { - 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 + c.logDepth(s, 3) // logDepth + log + public function } -// callSite retrieves and formats the file and line of the call site. -func (c *common) callSite(skip int) string { +// logDepth generates the output at an arbitrary stack depth. +func (c *common) logDepth(s string, depth int) { 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) + 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 + } } + panic("Log in goroutine after " + c.name + " has completed: " + s) } else { - file = "???" - } - if line == 0 { - line = 1 - } - - 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 -} + 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)) + } -// 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) + return } - return + c.output = append(c.output, c.decorate(s, depth+1)...) } - 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], @@ -1818,8 +1739,6 @@ 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) @@ -1867,10 +1786,6 @@ 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 @@ -1936,7 +1851,6 @@ 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)