testing: improve output

This introduces a few changes
- Skipped benchmarks now print a SKIP line, also if there was
no output
- The benchmark name is only printed if there the benchmark
was not skipped or did not fail in the probe phase.

It also fixes a bug of doubling a skip message in chatty mode in
absense of a failure.

The chatty flag is now passed in the common struct to allow
for testing of the printed messages.

Fixes #14799

Change-Id: Ia8eb140c2e5bb467e66b8ef20a2f98f5d95415d5
Reviewed-on: https://go-review.googlesource.com/21504
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Marcel van Lohuizen <mpvl@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>

src/testing/benchmark.go

@@ -208,7 +208,24 @@ func (b *B) run1() bool {
 		b.runN(1)
 	}()
 	<-b.signal
-	return !b.hasSub
+	if b.failed {
+		fmt.Fprintf(b.w, "--- FAIL: %s\n%s", b.name, b.output)
+		return false
+	}
+	// Only print the output if we know we are not going to proceed.
+	// Otherwise it is printed in processBench.
+	if b.hasSub || b.finished {
+		tag := "BENCH"
+		if b.skipped {
+			tag = "SKIP"
+		}
+		if b.chatty && (len(b.output) > 0 || b.finished) {
+			b.trimOutput()
+			fmt.Fprintf(b.w, "--- %s: %s\n%s", tag, b.name, b.output)
+		}
+		return false
+	}
+	return true
 }
 
 // run executes the benchmark in a separate goroutine, including all of its
@@ -372,7 +389,11 @@ func runBenchmarksInternal(matchString func(pat, str string) (bool, error), benc
 		}
 	}
 	main := &B{
-		common: common{name: "Main"},
+		common: common{
+			name:   "Main",
+			w:      os.Stdout,
+			chatty: *chatty,
+		},
 		benchFunc: func(b *B) {
 			for _, Benchmark := range bs {
 				b.Run(Benchmark.Name, Benchmark.F)
@@ -390,13 +411,15 @@ func (ctx *benchContext) processBench(b *B) {
 	for i, procs := range cpuList {
 		runtime.GOMAXPROCS(procs)
 		benchName := benchmarkName(b.name, procs)
-		fmt.Printf("%-*s\t", ctx.maxLen, benchName)
+		fmt.Fprintf(b.w, "%-*s\t", ctx.maxLen, benchName)
 		// Recompute the running time for all but the first iteration.
 		if i > 0 {
 			b = &B{
 				common: common{
 					signal: make(chan bool),
 					name:   b.name,
+					w:      b.w,
+					chatty: b.chatty,
 				},
 				benchFunc: b.benchFunc,
 				benchTime: b.benchTime,
@@ -408,19 +431,19 @@ func (ctx *benchContext) processBench(b *B) {
 			// The output could be very long here, but probably isn't.
 			// We print it all, regardless, because we don't want to trim the reason
 			// the benchmark failed.
-			fmt.Printf("--- FAIL: %s\n%s", benchName, b.output)
+			fmt.Fprintf(b.w, "--- FAIL: %s\n%s", benchName, b.output)
 			continue
 		}
 		results := r.String()
 		if *benchmarkMemory || b.showAllocResult {
 			results += "\t" + r.MemString()
 		}
-		fmt.Println(results)
+		fmt.Fprintln(b.w, results)
 		// Unlike with tests, we ignore the -chatty flag and always print output for
 		// benchmarks since the output generation time will skew the results.
 		if len(b.output) > 0 {
 			b.trimOutput()
-			fmt.Printf("--- BENCH: %s\n%s", benchName, b.output)
+			fmt.Fprintf(b.w, "--- BENCH: %s\n%s", benchName, b.output)
 		}
 		if p := runtime.GOMAXPROCS(-1); p != procs {
 			fmt.Fprintf(os.Stderr, "testing: %s left GOMAXPROCS set to %d\n", benchName, p)
@@ -453,6 +476,8 @@ func (b *B) Run(name string, f func(b *B)) bool {
 			name:   benchName,
 			parent: &b.common,
 			level:  b.level + 1,
+			w:      b.w,
+			chatty: b.chatty,
 		},
 		benchFunc: f,
 		benchTime: b.benchTime,
@@ -597,9 +622,17 @@ func Benchmark(f func(b *B)) BenchmarkResult {
 	b := &B{
 		common: common{
 			signal: make(chan bool),
+			w:      discard{},
 		},
 		benchFunc: f,
 		benchTime: *benchTime,
 	}
+	if !b.run1() {
+		return BenchmarkResult{}
+	}
 	return b.run()
 }
+
+type discard struct{}
+
+func (discard) Write(b []byte) (n int, err error) { return len(b), nil }

src/testing/sub_test.go

@@ -5,8 +5,9 @@
 package testing
 
 import (
-	"io/ioutil"
+	"bytes"
 	"regexp"
+	"strings"
 	"sync/atomic"
 	"time"
 )
@@ -113,11 +114,17 @@ func TestTRun(t *T) {
 		desc   string
 		ok     bool
 		maxPar int
+		chatty bool
+		output string
 		f      func(*T)
 	}{{
 		desc:   "failnow skips future sequential and parallel tests at same level",
 		ok:     false,
 		maxPar: 1,
+		output: `
+--- FAIL: failnow skips future sequential and parallel tests at same level (0.00s)
+    --- FAIL: failnow skips future sequential and parallel tests at same level/#00 (0.00s)
+    `,
 		f: func(t *T) {
 			ranSeq := false
 			ranPar := false
@@ -149,6 +156,11 @@ func TestTRun(t *T) {
 		desc:   "failure in parallel test propagates upwards",
 		ok:     false,
 		maxPar: 1,
+		output: `
+--- FAIL: failure in parallel test propagates upwards (0.00s)
+    --- FAIL: failure in parallel test propagates upwards/#00 (0.00s)
+        --- FAIL: failure in parallel test propagates upwards/#00/par (0.00s)
+		`,
 		f: func(t *T) {
 			t.Run("", func(t *T) {
 				t.Parallel()
@@ -158,6 +170,28 @@ func TestTRun(t *T) {
 				})
 			})
 		},
+	}, {
+		desc:   "skipping without message, chatty",
+		ok:     true,
+		chatty: true,
+		output: `
+=== RUN   skipping without message, chatty
+--- SKIP: skipping without message, chatty (0.00s)`,
+		f: func(t *T) { t.SkipNow() },
+	}, {
+		desc: "skipping without message, not chatty",
+		ok:   true,
+		f:    func(t *T) { t.SkipNow() },
+	}, {
+		desc: "skipping after error",
+		output: `
+--- FAIL: skipping after error (0.00s)
+	sub_test.go:nnn: an error
+	sub_test.go:nnn: skipped`,
+		f: func(t *T) {
+			t.Error("an error")
+			t.Skip("skipped")
+		},
 	}, {
 		desc:   "use Run to locally synchronize parallelism",
 		ok:     true,
@@ -301,14 +335,23 @@ func TestTRun(t *T) {
 				})
 			}
 		},
+	}, {
+		desc:   "skip output",
+		ok:     true,
+		maxPar: 4,
+		f: func(t *T) {
+			t.Skip()
+		},
 	}}
 	for _, tc := range testCases {
 		ctx := newTestContext(tc.maxPar, newMatcher(regexp.MatchString, "", ""))
+		buf := &bytes.Buffer{}
 		root := &T{
 			common: common{
 				signal: make(chan bool),
 				name:   "Test",
-				w:      ioutil.Discard,
+				w:      buf,
+				chatty: tc.chatty,
 			},
 			context: ctx,
 		}
@@ -324,6 +367,11 @@ func TestTRun(t *T) {
 		if ctx.running != 0 || ctx.numWaiting != 0 {
 			t.Errorf("%s:running and waiting non-zero: got %d and %d", tc.desc, ctx.running, ctx.numWaiting)
 		}
+		got := sanitizeLog(buf.String())
+		want := sanitizeLog(tc.output)
+		if got != want {
+			t.Errorf("%s:ouput:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
+		}
 	}
 }
 
@@ -336,6 +384,8 @@ func TestBRun(t *T) {
 	testCases := []struct {
 		desc   string
 		failed bool
+		chatty bool
+		output string
 		f      func(*B)
 	}{{
 		desc: "simulate sequential run of subbenchmarks.",
@@ -371,7 +421,34 @@ func TestBRun(t *T) {
 	}, {
 		desc:   "failure carried over to root",
 		failed: true,
+		output: "--- FAIL: root",
 		f:      func(b *B) { b.Fail() },
+	}, {
+		desc:   "skipping without message, chatty",
+		chatty: true,
+		output: "--- SKIP: root",
+		f:      func(b *B) { b.SkipNow() },
+	}, {
+		desc:   "skipping with message, chatty",
+		chatty: true,
+		output: `
+--- SKIP: root
+	sub_test.go:: skipping`,
+		f: func(b *B) { b.Skip("skipping") },
+	}, {
+		desc: "skipping without message, not chatty",
+		f:    func(b *B) { b.SkipNow() },
+	}, {
+		desc:   "skipping after error",
+		failed: true,
+		output: `
+--- FAIL: root
+	sub_test.go:nnn: an error
+	sub_test.go:nnn: skipped`,
+		f: func(b *B) {
+			b.Error("an error")
+			b.Skip("skipped")
+		},
 	}, {
 		desc: "memory allocation",
 		f: func(b *B) {
@@ -398,11 +475,15 @@ func TestBRun(t *T) {
 	}}
 	for _, tc := range testCases {
 		var ok bool
+		buf := &bytes.Buffer{}
 		// This is almost like the Benchmark function, except that we override
 		// the benchtime and catch the failure result of the subbenchmark.
 		root := &B{
 			common: common{
 				signal: make(chan bool),
+				name:   "root",
+				w:      buf,
+				chatty: tc.chatty,
 			},
 			benchFunc: func(b *B) { ok = b.Run("test", tc.f) }, // Use Run to catch failure.
 			benchTime: time.Microsecond,
@@ -418,5 +499,30 @@ func TestBRun(t *T) {
 		if root.result.N != 1 {
 			t.Errorf("%s: N for parent benchmark was %d; want 1", tc.desc, root.result.N)
 		}
+		got := sanitizeLog(buf.String())
+		want := sanitizeLog(tc.output)
+		if got != want {
+			t.Errorf("%s:ouput:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
+		}
 	}
 }
+
+// sanitizeLog removes line numbers from log entries.
+func sanitizeLog(s string) string {
+	s = strings.TrimSpace(s)
+	lines := strings.Split(s, "\n")
+	for i, line := range lines {
+		p := strings.IndexByte(line, ':')
+		if p > 0 && line[p+4] == ':' { // assuming 3-digit file positions
+			lines[i] = line[:p+1] + line[p+4:]
+		}
+	}
+	return strings.Join(lines, "\n")
+}
+
+func TestBenchmarkOutput(t *T) {
+	// Ensure Benchmark initialized common.w by invoking it with an error and
+	// normal case.
+	Benchmark(func(b *B) { b.Error("do not print this output") })
+	Benchmark(func(b *B) {})
+}

src/testing/testing.go

@@ -199,6 +199,7 @@ type common struct {
 	mu       sync.RWMutex // guards output and failed
 	output   []byte       // Output generated by test or benchmark.
 	w        io.Writer    // For flushToParent.
+	chatty   bool         // A copy of the chatty flag.
 	failed   bool         // Test or benchmark has failed.
 	skipped  bool         // Test of benchmark has been skipped.
 	finished bool
@@ -265,7 +266,6 @@ func (c *common) flushToParent(format string, args ...interface{}) {
 	defer p.mu.Unlock()
 
 	fmt.Fprintf(p.w, format, args...)
-	fmt.Fprintln(p.w)
 
 	c.mu.Lock()
 	defer c.mu.Unlock()
@@ -562,13 +562,18 @@ func (t *T) Run(name string, f func(t *T)) bool {
 			name:    testName,
 			parent:  &t.common,
 			level:   t.level + 1,
+			chatty:  t.chatty,
 		},
 		context: t.context,
 	}
 	t.w = indenter{&t.common}
 
-	if *chatty {
+	if t.chatty {
-		fmt.Printf("=== RUN   %s\n", t.name)
+		// Print directly to root's io.Writer so there is no delay.
+		root := t.parent
+		for ; root.parent != nil; root = t.parent {
+		}
+		fmt.Fprintf(root.w, "=== RUN   %s\n", t.name)
 	}
 	// Instead of reducing the running count of this test before calling the
 	// tRunner and increasing it afterwards, we rely on tRunner keeping the
@@ -690,10 +695,10 @@ func (t *T) report() {
 		return
 	}
 	dstr := fmtDuration(t.duration)
-	format := "--- %s: %s (%s)"
+	format := "--- %s: %s (%s)\n"
 	if t.Failed() {
 		t.flushToParent(format, "FAIL", t.name, dstr)
-	} else if *chatty {
+	} else if t.chatty {
 		if t.Skipped() {
 			t.flushToParent(format, "SKIP", t.name, dstr)
 		} else {
@@ -716,6 +721,7 @@ func RunTests(matchString func(pat, str string) (bool, error), tests []InternalT
 				signal:  make(chan bool),
 				barrier: make(chan bool),
 				w:       os.Stdout,
+				chatty:  *chatty,
 			},
 			context: ctx,
 		}