Revert "testing: add Output"

This reverts commit 8d189f188e.

Reason for revert: failing test

Change-Id: I951087eaef7818697acf87e3206003bcc8a81ee2
Reviewed-on: https://go-review.googlesource.com/c/go/+/672335
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Jonathan Amsterdam <jba@google.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
Reviewed-by: Michael Knyszek <mknyszek@google.com>
This commit is contained in:
Jonathan Amsterdam 2025-05-13 11:50:58 -07:00 committed by Gopher Robot
parent 9bba799955
commit afd6b0bc66
7 changed files with 68 additions and 446 deletions

View File

@ -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

View File

@ -1,4 +0,0 @@
<!-- go.dev/issue/59928 -->
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.

View File

@ -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()
}

View File

@ -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)
}

View File

@ -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() {

View File

@ -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)
}
}

View File

@ -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")
c.logDepth(s, 3) // logDepth + log + public function
}
// 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.
// logDepth generates the output at an arbitrary stack depth.
func (c *common) logDepth(s string, depth int) {
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
}
}
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
}
// 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)
}
} else {
file = "???"
}
if line == 0 {
line = 1
}
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))
}
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]
return
}
o.writeLine(line)
c.output = append(c.output, c.decorate(s, depth+1)...)
}
// 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)
}
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],
@ -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)