testing: flush test summaries to stdout atomically when streaming output
While debugging #40771, I realized that the chatty printer should only
ever print to a single io.Writer (normally os.Stdout). The other
Writer implementations in the chain write to local buffers, but if we
wrote a test's output to a local buffer, then we did *not* write it to
stdout and we should not store it as the most recently logged test.
Because the chatty printer should only ever print to one place, it
shouldn't receive an io.Writer as an argument — rather, it shouldn't
be used at all for destinations other than the main output stream.
On the other hand, when we flush the output buffer to stdout in the
top-level flushToParent call, it is important that we not allow some
other test's output to intrude between the test summary header and the
remainder of the test's output. cmd/test2json doesn't know how to
parse such an intrusion, and it's confusing to humans too.
No test because I couldn't reproduce the user-reported error without
modifying the testing package. (This behavior seems to be very
sensitive to output size and/or goroutine scheduling.)
Fixes #40771
Updates #38458
Change-Id: Ic19bf1d535672b096ba1c8583a3b74aab6d6d766
Reviewed-on: https://go-review.googlesource.com/c/go/+/249026
Run-TryBot: Bryan C. Mills <bcmills@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Jay Conrod <jayconrod@google.com>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
diff --git a/src/testing/benchmark.go b/src/testing/benchmark.go
index 5276600..e9687bf 100644
--- a/src/testing/benchmark.go
+++ b/src/testing/benchmark.go
@@ -242,7 +242,7 @@
if b.skipped {
tag = "SKIP"
}
- if b.chatty && (len(b.output) > 0 || b.finished) {
+ if b.chatty != nil && (len(b.output) > 0 || b.finished) {
b.trimOutput()
fmt.Fprintf(b.w, "--- %s: %s\n%s", tag, b.name, b.output)
}
@@ -523,10 +523,9 @@
}
main := &B{
common: common{
- name: "Main",
- w: os.Stdout,
- chatty: *chatty,
- bench: true,
+ name: "Main",
+ w: os.Stdout,
+ bench: true,
},
importPath: importPath,
benchFunc: func(b *B) {
@@ -537,6 +536,9 @@
benchTime: benchTime,
context: ctx,
}
+ if Verbose() {
+ main.chatty = newChattyPrinter(main.w)
+ }
main.runN(1)
return !main.failed
}
@@ -549,7 +551,7 @@
benchName := benchmarkName(b.name, procs)
// If it's chatty, we've already printed this information.
- if !b.chatty {
+ if b.chatty == nil {
fmt.Fprintf(b.w, "%-*s\t", ctx.maxLen, benchName)
}
// Recompute the running time for all but the first iteration.
@@ -576,7 +578,7 @@
continue
}
results := r.String()
- if b.chatty {
+ if b.chatty != nil {
fmt.Fprintf(b.w, "%-*s\t", ctx.maxLen, benchName)
}
if *benchmarkMemory || b.showAllocResult {
@@ -639,7 +641,7 @@
atomic.StoreInt32(&sub.hasSub, 1)
}
- if b.chatty {
+ if b.chatty != nil {
labelsOnce.Do(func() {
fmt.Printf("goos: %s\n", runtime.GOOS)
fmt.Printf("goarch: %s\n", runtime.GOARCH)
diff --git a/src/testing/sub_test.go b/src/testing/sub_test.go
index 51fc0cc..5b226f8 100644
--- a/src/testing/sub_test.go
+++ b/src/testing/sub_test.go
@@ -483,10 +483,12 @@
signal: make(chan bool),
name: "Test",
w: buf,
- chatty: tc.chatty,
},
context: ctx,
}
+ if tc.chatty {
+ root.chatty = newChattyPrinter(root.w)
+ }
ok := root.Run(tc.desc, tc.f)
ctx.release()
@@ -665,11 +667,13 @@
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: benchTimeFlag{d: 1 * time.Microsecond},
}
+ if tc.chatty {
+ root.chatty = newChattyPrinter(root.w)
+ }
root.runN(1)
if ok != !tc.failed {
t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, !tc.failed)
@@ -741,9 +745,13 @@
}
}
-type funcWriter func([]byte) (int, error)
+type funcWriter struct {
+ write func([]byte) (int, error)
+}
-func (fw funcWriter) Write(b []byte) (int, error) { return fw(b) }
+func (fw *funcWriter) Write(b []byte) (int, error) {
+ return fw.write(b)
+}
func TestRacyOutput(t *T) {
var runs int32 // The number of running Writes
@@ -761,9 +769,10 @@
var wg sync.WaitGroup
root := &T{
- common: common{w: funcWriter(raceDetector), chatty: true},
+ common: common{w: &funcWriter{raceDetector}},
context: newTestContext(1, newMatcher(regexp.MatchString, "", "")),
}
+ root.chatty = newChattyPrinter(root.w)
root.Run("", func(t *T) {
for i := 0; i < 100; i++ {
wg.Add(1)
diff --git a/src/testing/testing.go b/src/testing/testing.go
index f4f0060..a64206f 100644
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -327,7 +327,6 @@
cpuListStr *string
parallel *int
testlog *string
- printer *testPrinter
haveExamples bool // are there examples?
@@ -337,55 +336,45 @@
numFailed uint32 // number of test failures
)
-type testPrinter struct {
- chatty bool
-
+type chattyPrinter struct {
+ w io.Writer
lastNameMu sync.Mutex // guards lastName
lastName string // last printed test name in chatty mode
}
-func newTestPrinter(chatty bool) *testPrinter {
- return &testPrinter{
- chatty: chatty,
- }
+func newChattyPrinter(w io.Writer) *chattyPrinter {
+ return &chattyPrinter{w: w}
}
-func (p *testPrinter) Print(testName, out string) {
- p.Fprint(os.Stdout, testName, out)
-}
-
-func (p *testPrinter) Fprint(w io.Writer, testName, out string) {
+// Updatef prints a message about the status of the named test to w.
+//
+// The formatted message must include the test name itself.
+func (p *chattyPrinter) Updatef(testName, format string, args ...interface{}) {
p.lastNameMu.Lock()
defer p.lastNameMu.Unlock()
- if !p.chatty ||
- strings.HasPrefix(out, "--- PASS: ") ||
- strings.HasPrefix(out, "--- FAIL: ") ||
- strings.HasPrefix(out, "--- SKIP: ") ||
- strings.HasPrefix(out, "=== RUN ") ||
- strings.HasPrefix(out, "=== CONT ") ||
- strings.HasPrefix(out, "=== PAUSE ") {
- // If we're buffering test output (!p.chatty), we don't really care which
- // test is emitting which line so long as they are serialized.
- //
- // If the message already implies an association with a specific new test,
- // we don't need to check what the old test name was or log an extra CONT
- // line for it. (We're updating it anyway, and the current message already
- // includes the test name.)
- p.lastName = testName
- fmt.Fprint(w, out)
- return
- }
+ // Since the message already implies an association with a specific new test,
+ // we don't need to check what the old test name was or log an extra CONT line
+ // for it. (We're updating it anyway, and the current message already includes
+ // the test name.)
+ p.lastName = testName
+ fmt.Fprintf(p.w, format, args...)
+}
+
+// Printf prints a message, generated by the named test, that does not
+// necessarily mention that tests's name itself.
+func (p *chattyPrinter) Printf(testName, format string, args ...interface{}) {
+ p.lastNameMu.Lock()
+ defer p.lastNameMu.Unlock()
if p.lastName == "" {
p.lastName = testName
} else if p.lastName != testName {
- // Always printed as-is, with 0 decoration or indentation. So, we skip
- // printing to w.
- fmt.Printf("=== CONT %s\n", testName)
+ fmt.Fprintf(p.w, "=== CONT %s\n", testName)
p.lastName = testName
}
- fmt.Fprint(w, out)
+
+ fmt.Fprintf(p.w, format, args...)
}
// The maximum number of stack frames to go through when skipping helper functions for
@@ -407,12 +396,12 @@
cleanupName string // Name of the cleanup function.
cleanupPc []uintptr // The stack trace at the point where Cleanup was called.
- chatty bool // A copy of the chatty flag.
- bench bool // Whether the current test is a benchmark.
- finished bool // Test function has completed.
- hasSub int32 // Written atomically.
- raceErrors int // Number of races detected during test.
- runner string // Function name of tRunner running the test.
+ chatty *chattyPrinter // A copy of chattyPrinter, if the chatty flag is set.
+ bench bool // Whether the current test is a benchmark.
+ finished bool // Test function has completed.
+ hasSub int32 // Written atomically.
+ raceErrors int // Number of races detected during test.
+ runner string // Function name of tRunner running the test.
parent *common
level int // Nesting depth of test or benchmark.
@@ -574,12 +563,31 @@
p.mu.Lock()
defer p.mu.Unlock()
- printer.Fprint(p.w, testName, fmt.Sprintf(format, args...))
-
c.mu.Lock()
defer c.mu.Unlock()
- io.Copy(p.w, bytes.NewReader(c.output))
- c.output = c.output[:0]
+
+ if len(c.output) > 0 {
+ format += "%s"
+ args = append(args[:len(args):len(args)], c.output)
+ c.output = c.output[:0] // but why?
+ }
+
+ if c.chatty != nil && p.w == c.chatty.w {
+ // We're flushing to the actual output, so track that this output is
+ // associated with a specific test (and, specifically, that the next output
+ // is *not* associated with that test).
+ //
+ // Moreover, if c.output is non-empty it is important that this write be
+ // atomic with respect to the output of other tests, so that we don't end up
+ // with confusing '=== CONT' lines in the middle of our '--- PASS' block.
+ // Neither humans nor cmd/test2json can parse those easily.
+ // (See https://golang.org/issue/40771.)
+ c.chatty.Updatef(testName, format, args...)
+ } else {
+ // We're flushing to the output buffer of the parent test, which will
+ // itself follow a test-name header when it is finally flushed to stdout.
+ fmt.Fprintf(p.w, format, args...)
+ }
}
type indenter struct {
@@ -748,13 +756,13 @@
}
panic("Log in goroutine after " + c.name + " has completed")
} else {
- if c.chatty {
+ 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 {
- printer.Print(c.name, c.decorate(s, depth+1))
+ c.chatty.Printf(c.name, "%s", c.decorate(s, depth+1))
}
return
@@ -1003,34 +1011,22 @@
t.parent.sub = append(t.parent.sub, t)
t.raceErrors += race.Errors()
- if t.chatty {
- // Print directly to root's io.Writer so there is no delay.
- root := t.parent
- for ; root.parent != nil; root = root.parent {
- }
- root.mu.Lock()
+ if t.chatty != nil {
// Unfortunately, even though PAUSE indicates that the named test is *no
// longer* running, cmd/test2json interprets it as changing the active test
// for the purpose of log parsing. We could fix cmd/test2json, but that
// won't fix existing deployments of third-party tools that already shell
// out to older builds of cmd/test2json — so merely fixing cmd/test2json
// isn't enough for now.
- printer.Fprint(root.w, t.name, fmt.Sprintf("=== PAUSE %s\n", t.name))
- root.mu.Unlock()
+ t.chatty.Updatef(t.name, "=== PAUSE %s\n", t.name)
}
t.signal <- true // Release calling test.
<-t.parent.barrier // Wait for the parent test to complete.
t.context.waitParallel()
- if t.chatty {
- // Print directly to root's io.Writer so there is no delay.
- root := t.parent
- for ; root.parent != nil; root = root.parent {
- }
- root.mu.Lock()
- printer.Fprint(root.w, t.name, fmt.Sprintf("=== CONT %s\n", t.name))
- root.mu.Unlock()
+ if t.chatty != nil {
+ t.chatty.Updatef(t.name, "=== CONT %s\n", t.name)
}
t.start = time.Now()
@@ -1181,14 +1177,8 @@
}
t.w = indenter{&t.common}
- if t.chatty {
- // Print directly to root's io.Writer so there is no delay.
- root := t.parent
- for ; root.parent != nil; root = root.parent {
- }
- root.mu.Lock()
- printer.Fprint(root.w, t.name, fmt.Sprintf("=== RUN %s\n", t.name))
- root.mu.Unlock()
+ if t.chatty != nil {
+ t.chatty.Updatef(t.name, "=== 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
@@ -1355,8 +1345,6 @@
flag.Parse()
}
- printer = newTestPrinter(Verbose())
-
if *parallel < 1 {
fmt.Fprintln(os.Stderr, "testing: -parallel can only be given a positive integer")
flag.Usage()
@@ -1401,7 +1389,7 @@
format := "--- %s: %s (%s)\n"
if t.Failed() {
t.flushToParent(t.name, format, "FAIL", t.name, dstr)
- } else if t.chatty {
+ } else if t.chatty != nil {
if t.Skipped() {
t.flushToParent(t.name, format, "SKIP", t.name, dstr)
} else {
@@ -1462,10 +1450,12 @@
signal: make(chan bool),
barrier: make(chan bool),
w: os.Stdout,
- chatty: *chatty,
},
context: ctx,
}
+ if Verbose() {
+ t.chatty = newChattyPrinter(t.w)
+ }
tRunner(t, func(t *T) {
for _, test := range tests {
t.Run(test.Name, test.F)
