From c25dd3f8325a5022a2573c71afd810f3fb604b08 Mon Sep 17 00:00:00 2001 From: "Bryan C. Mills" Date: Tue, 18 Aug 2020 22:47:12 -0400 Subject: [PATCH] [release-branch.go1.15] testing: flush test summaries to stdout atomically when streaming output MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 #40881 Updates #40771 Updates #38458 Change-Id: Ic19bf1d535672b096ba1c8583a3b74aab6d6d766 Reviewed-on: https://go-review.googlesource.com/c/go/+/249026 Run-TryBot: Bryan C. Mills TryBot-Result: Gobot Gobot Reviewed-by: Jay Conrod Reviewed-by: Ian Lance Taylor (cherry picked from commit 51c0bdc6d15dcd7f753c25896039ab41ac787ebb) Reviewed-on: https://go-review.googlesource.com/c/go/+/252637 TryBot-Result: Go Bot Trust: Bryan C. Mills --- src/testing/benchmark.go | 18 ++--- src/testing/sub_test.go | 19 ++++-- src/testing/testing.go | 140 ++++++++++++++++++--------------------- 3 files changed, 89 insertions(+), 88 deletions(-) diff --git a/src/testing/benchmark.go b/src/testing/benchmark.go index 52766005bf..e9687bf26d 100644 --- a/src/testing/benchmark.go +++ b/src/testing/benchmark.go @@ -242,7 +242,7 @@ func (b *B) run1() bool { 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 @@ func runBenchmarks(importPath string, matchString func(pat, str string) (bool, e } 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 @@ func runBenchmarks(importPath string, matchString func(pat, str string) (bool, e benchTime: benchTime, context: ctx, } + if Verbose() { + main.chatty = newChattyPrinter(main.w) + } main.runN(1) return !main.failed } @@ -549,7 +551,7 @@ func (ctx *benchContext) processBench(b *B) { 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 @@ func (ctx *benchContext) processBench(b *B) { 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 @@ func (b *B) Run(name string, f func(b *B)) bool { 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 8eb0084b1c..5ed3fc4afe 100644 --- a/src/testing/sub_test.go +++ b/src/testing/sub_test.go @@ -483,10 +483,12 @@ func TestTRun(t *T) { 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 @@ func TestBRun(t *T) { 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 @@ func TestParallelSub(t *T) { } } -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 @@ func TestRacyOutput(t *T) { 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 bf83df8863..0055a4cfe2 100644 --- a/src/testing/testing.go +++ b/src/testing/testing.go @@ -325,7 +325,6 @@ var ( cpuListStr *string parallel *int testlog *string - printer *testPrinter haveExamples bool // are there examples? @@ -335,55 +334,45 @@ var ( 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 @@ -405,12 +394,12 @@ type common struct { 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. @@ -572,12 +561,31 @@ func (c *common) flushToParent(testName, format string, args ...interface{}) { 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 { @@ -746,13 +754,13 @@ func (c *common) logDepth(s string, depth int) { } 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 @@ -983,34 +991,22 @@ func (t *T) Parallel() { 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() @@ -1161,14 +1157,8 @@ func (t *T) Run(name string, f func(t *T)) bool { } 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 @@ -1333,8 +1323,6 @@ func (m *M) Run() (code int) { flag.Parse() } - printer = newTestPrinter(Verbose()) - if *parallel < 1 { fmt.Fprintln(os.Stderr, "testing: -parallel can only be given a positive integer") flag.Usage() @@ -1379,7 +1367,7 @@ func (t *T) report() { 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 { @@ -1440,10 +1428,12 @@ 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, } + if Verbose() { + t.chatty = newChattyPrinter(t.w) + } tRunner(t, func(t *T) { for _, test := range tests { t.Run(test.Name, test.F)