+++ /dev/null
-pkg testing, method (*B) Output() io.Writer #59928
-pkg testing, method (*F) Output() io.Writer #59928
-pkg testing, method (*T) Output() io.Writer #59928
+++ /dev/null
-<!-- 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.
benchFunc: b.benchFunc,
benchTime: b.benchTime,
}
- b.setOutputWriter()
b.run1()
}
r := b.doBench()
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.
benchFunc: f,
benchTime: benchTime,
}
- b.setOutputWriter()
if b.run1() {
b.run()
}
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)
}
fstate: fstate,
}
f.w = indenter{&f.common}
- f.setOutputWriter()
if f.chatty != nil {
f.chatty.Updatef(f.name, "=== RUN %s\n", f.name)
}
want: `
--- FAIL: TestPanicHelper (N.NNs)
panic_test.go:NNN: TestPanicHelper
- TestPanicHelper
`,
}, {
desc: "subtest panics",
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",
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",
ran outer cleanup
--- FAIL: TestPanicHelper (N.NNs)
panic_test.go:NNN: TestPanicHelper
- TestPanicHelper
`,
}, {
desc: "subtest panics with middle cleanup panic",
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",
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",
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",
ran outer cleanup
--- FAIL: TestPanicHelper (N.NNs)
panic_test.go:NNN: TestPanicHelper
- TestPanicHelper
`,
}, {
desc: "parallel subtest panics with middle cleanup panic",
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",
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 {
return
}
t.Log(t.Name())
- t.Output().Write([]byte(t.Name()))
if t.Name() == *testPanicTest {
panic("panic")
}
t.Parallel()
}
t.Log(t.Name())
- t.Output().Write([]byte(t.Name()))
if chosen {
if *testPanicCleanup {
t.Cleanup(func() {
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) {
}
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"
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)
- }
-}
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.
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) {
c *common
}
-const indent = " "
-
func (w indenter) Write(b []byte) (n int, err error) {
n = len(b)
for len(b) > 0 {
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:]
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],
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)
// 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
tstate: t.tstate,
}
t.w = indenter{&t.common}
- t.setOutputWriter()
if t.chatty != nil {
t.chatty.Updatef(t.name, "=== RUN %s\n", t.name)