Skip to content

Commit c25dd3f

Browse files
Bryan C. Millsdmitshur
Bryan C. Mills
authored andcommitted
[release-branch.go1.15] 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 #40881 Updates #40771 Updates #38458 Change-Id: Ic19bf1d535672b096ba1c8583a3b74aab6d6d766 Reviewed-on: https://go-review.googlesource.com/c/go/+/249026 Run-TryBot: Bryan C. Mills <[email protected]> TryBot-Result: Gobot Gobot <[email protected]> Reviewed-by: Jay Conrod <[email protected]> Reviewed-by: Ian Lance Taylor <[email protected]> (cherry picked from commit 51c0bdc) Reviewed-on: https://go-review.googlesource.com/c/go/+/252637 TryBot-Result: Go Bot <[email protected]> Trust: Bryan C. Mills <[email protected]>
1 parent fa262e6 commit c25dd3f

File tree

3 files changed

+88
-87
lines changed

3 files changed

+88
-87
lines changed

src/testing/benchmark.go

Lines changed: 10 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -242,7 +242,7 @@ func (b *B) run1() bool {
242242
if b.skipped {
243243
tag = "SKIP"
244244
}
245-
if b.chatty && (len(b.output) > 0 || b.finished) {
245+
if b.chatty != nil && (len(b.output) > 0 || b.finished) {
246246
b.trimOutput()
247247
fmt.Fprintf(b.w, "--- %s: %s\n%s", tag, b.name, b.output)
248248
}
@@ -523,10 +523,9 @@ func runBenchmarks(importPath string, matchString func(pat, str string) (bool, e
523523
}
524524
main := &B{
525525
common: common{
526-
name: "Main",
527-
w: os.Stdout,
528-
chatty: *chatty,
529-
bench: true,
526+
name: "Main",
527+
w: os.Stdout,
528+
bench: true,
530529
},
531530
importPath: importPath,
532531
benchFunc: func(b *B) {
@@ -537,6 +536,9 @@ func runBenchmarks(importPath string, matchString func(pat, str string) (bool, e
537536
benchTime: benchTime,
538537
context: ctx,
539538
}
539+
if Verbose() {
540+
main.chatty = newChattyPrinter(main.w)
541+
}
540542
main.runN(1)
541543
return !main.failed
542544
}
@@ -549,7 +551,7 @@ func (ctx *benchContext) processBench(b *B) {
549551
benchName := benchmarkName(b.name, procs)
550552

551553
// If it's chatty, we've already printed this information.
552-
if !b.chatty {
554+
if b.chatty == nil {
553555
fmt.Fprintf(b.w, "%-*s\t", ctx.maxLen, benchName)
554556
}
555557
// Recompute the running time for all but the first iteration.
@@ -576,7 +578,7 @@ func (ctx *benchContext) processBench(b *B) {
576578
continue
577579
}
578580
results := r.String()
579-
if b.chatty {
581+
if b.chatty != nil {
580582
fmt.Fprintf(b.w, "%-*s\t", ctx.maxLen, benchName)
581583
}
582584
if *benchmarkMemory || b.showAllocResult {
@@ -639,7 +641,7 @@ func (b *B) Run(name string, f func(b *B)) bool {
639641
atomic.StoreInt32(&sub.hasSub, 1)
640642
}
641643

642-
if b.chatty {
644+
if b.chatty != nil {
643645
labelsOnce.Do(func() {
644646
fmt.Printf("goos: %s\n", runtime.GOOS)
645647
fmt.Printf("goarch: %s\n", runtime.GOARCH)

src/testing/sub_test.go

Lines changed: 14 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -483,10 +483,12 @@ func TestTRun(t *T) {
483483
signal: make(chan bool),
484484
name: "Test",
485485
w: buf,
486-
chatty: tc.chatty,
487486
},
488487
context: ctx,
489488
}
489+
if tc.chatty {
490+
root.chatty = newChattyPrinter(root.w)
491+
}
490492
ok := root.Run(tc.desc, tc.f)
491493
ctx.release()
492494

@@ -665,11 +667,13 @@ func TestBRun(t *T) {
665667
signal: make(chan bool),
666668
name: "root",
667669
w: buf,
668-
chatty: tc.chatty,
669670
},
670671
benchFunc: func(b *B) { ok = b.Run("test", tc.f) }, // Use Run to catch failure.
671672
benchTime: benchTimeFlag{d: 1 * time.Microsecond},
672673
}
674+
if tc.chatty {
675+
root.chatty = newChattyPrinter(root.w)
676+
}
673677
root.runN(1)
674678
if ok != !tc.failed {
675679
t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, !tc.failed)
@@ -741,9 +745,13 @@ func TestParallelSub(t *T) {
741745
}
742746
}
743747

744-
type funcWriter func([]byte) (int, error)
748+
type funcWriter struct {
749+
write func([]byte) (int, error)
750+
}
745751

746-
func (fw funcWriter) Write(b []byte) (int, error) { return fw(b) }
752+
func (fw *funcWriter) Write(b []byte) (int, error) {
753+
return fw.write(b)
754+
}
747755

748756
func TestRacyOutput(t *T) {
749757
var runs int32 // The number of running Writes
@@ -761,9 +769,10 @@ func TestRacyOutput(t *T) {
761769

762770
var wg sync.WaitGroup
763771
root := &T{
764-
common: common{w: funcWriter(raceDetector), chatty: true},
772+
common: common{w: &funcWriter{raceDetector}},
765773
context: newTestContext(1, newMatcher(regexp.MatchString, "", "")),
766774
}
775+
root.chatty = newChattyPrinter(root.w)
767776
root.Run("", func(t *T) {
768777
for i := 0; i < 100; i++ {
769778
wg.Add(1)

src/testing/testing.go

Lines changed: 64 additions & 74 deletions
Original file line numberDiff line numberDiff line change
@@ -325,7 +325,6 @@ var (
325325
cpuListStr *string
326326
parallel *int
327327
testlog *string
328-
printer *testPrinter
329328

330329
haveExamples bool // are there examples?
331330

@@ -335,55 +334,45 @@ var (
335334
numFailed uint32 // number of test failures
336335
)
337336

338-
type testPrinter struct {
339-
chatty bool
340-
337+
type chattyPrinter struct {
338+
w io.Writer
341339
lastNameMu sync.Mutex // guards lastName
342340
lastName string // last printed test name in chatty mode
343341
}
344342

345-
func newTestPrinter(chatty bool) *testPrinter {
346-
return &testPrinter{
347-
chatty: chatty,
348-
}
343+
func newChattyPrinter(w io.Writer) *chattyPrinter {
344+
return &chattyPrinter{w: w}
349345
}
350346

351-
func (p *testPrinter) Print(testName, out string) {
352-
p.Fprint(os.Stdout, testName, out)
347+
// Updatef prints a message about the status of the named test to w.
348+
//
349+
// The formatted message must include the test name itself.
350+
func (p *chattyPrinter) Updatef(testName, format string, args ...interface{}) {
351+
p.lastNameMu.Lock()
352+
defer p.lastNameMu.Unlock()
353+
354+
// Since the message already implies an association with a specific new test,
355+
// we don't need to check what the old test name was or log an extra CONT line
356+
// for it. (We're updating it anyway, and the current message already includes
357+
// the test name.)
358+
p.lastName = testName
359+
fmt.Fprintf(p.w, format, args...)
353360
}
354361

355-
func (p *testPrinter) Fprint(w io.Writer, testName, out string) {
362+
// Printf prints a message, generated by the named test, that does not
363+
// necessarily mention that tests's name itself.
364+
func (p *chattyPrinter) Printf(testName, format string, args ...interface{}) {
356365
p.lastNameMu.Lock()
357366
defer p.lastNameMu.Unlock()
358367

359-
if !p.chatty ||
360-
strings.HasPrefix(out, "--- PASS: ") ||
361-
strings.HasPrefix(out, "--- FAIL: ") ||
362-
strings.HasPrefix(out, "--- SKIP: ") ||
363-
strings.HasPrefix(out, "=== RUN ") ||
364-
strings.HasPrefix(out, "=== CONT ") ||
365-
strings.HasPrefix(out, "=== PAUSE ") {
366-
// If we're buffering test output (!p.chatty), we don't really care which
367-
// test is emitting which line so long as they are serialized.
368-
//
369-
// If the message already implies an association with a specific new test,
370-
// we don't need to check what the old test name was or log an extra CONT
371-
// line for it. (We're updating it anyway, and the current message already
372-
// includes the test name.)
373-
p.lastName = testName
374-
fmt.Fprint(w, out)
375-
return
376-
}
377-
378368
if p.lastName == "" {
379369
p.lastName = testName
380370
} else if p.lastName != testName {
381-
// Always printed as-is, with 0 decoration or indentation. So, we skip
382-
// printing to w.
383-
fmt.Printf("=== CONT %s\n", testName)
371+
fmt.Fprintf(p.w, "=== CONT %s\n", testName)
384372
p.lastName = testName
385373
}
386-
fmt.Fprint(w, out)
374+
375+
fmt.Fprintf(p.w, format, args...)
387376
}
388377

389378
// The maximum number of stack frames to go through when skipping helper functions for
@@ -405,12 +394,12 @@ type common struct {
405394
cleanupName string // Name of the cleanup function.
406395
cleanupPc []uintptr // The stack trace at the point where Cleanup was called.
407396

408-
chatty bool // A copy of the chatty flag.
409-
bench bool // Whether the current test is a benchmark.
410-
finished bool // Test function has completed.
411-
hasSub int32 // Written atomically.
412-
raceErrors int // Number of races detected during test.
413-
runner string // Function name of tRunner running the test.
397+
chatty *chattyPrinter // A copy of chattyPrinter, if the chatty flag is set.
398+
bench bool // Whether the current test is a benchmark.
399+
finished bool // Test function has completed.
400+
hasSub int32 // Written atomically.
401+
raceErrors int // Number of races detected during test.
402+
runner string // Function name of tRunner running the test.
414403

415404
parent *common
416405
level int // Nesting depth of test or benchmark.
@@ -572,12 +561,31 @@ func (c *common) flushToParent(testName, format string, args ...interface{}) {
572561
p.mu.Lock()
573562
defer p.mu.Unlock()
574563

575-
printer.Fprint(p.w, testName, fmt.Sprintf(format, args...))
576-
577564
c.mu.Lock()
578565
defer c.mu.Unlock()
579-
io.Copy(p.w, bytes.NewReader(c.output))
580-
c.output = c.output[:0]
566+
567+
if len(c.output) > 0 {
568+
format += "%s"
569+
args = append(args[:len(args):len(args)], c.output)
570+
c.output = c.output[:0] // but why?
571+
}
572+
573+
if c.chatty != nil && p.w == c.chatty.w {
574+
// We're flushing to the actual output, so track that this output is
575+
// associated with a specific test (and, specifically, that the next output
576+
// is *not* associated with that test).
577+
//
578+
// Moreover, if c.output is non-empty it is important that this write be
579+
// atomic with respect to the output of other tests, so that we don't end up
580+
// with confusing '=== CONT' lines in the middle of our '--- PASS' block.
581+
// Neither humans nor cmd/test2json can parse those easily.
582+
// (See https://golang.org/issue/40771.)
583+
c.chatty.Updatef(testName, format, args...)
584+
} else {
585+
// We're flushing to the output buffer of the parent test, which will
586+
// itself follow a test-name header when it is finally flushed to stdout.
587+
fmt.Fprintf(p.w, format, args...)
588+
}
581589
}
582590

583591
type indenter struct {
@@ -746,13 +754,13 @@ func (c *common) logDepth(s string, depth int) {
746754
}
747755
panic("Log in goroutine after " + c.name + " has completed")
748756
} else {
749-
if c.chatty {
757+
if c.chatty != nil {
750758
if c.bench {
751759
// Benchmarks don't print === CONT, so we should skip the test
752760
// printer and just print straight to stdout.
753761
fmt.Print(c.decorate(s, depth+1))
754762
} else {
755-
printer.Print(c.name, c.decorate(s, depth+1))
763+
c.chatty.Printf(c.name, "%s", c.decorate(s, depth+1))
756764
}
757765

758766
return
@@ -983,34 +991,22 @@ func (t *T) Parallel() {
983991
t.parent.sub = append(t.parent.sub, t)
984992
t.raceErrors += race.Errors()
985993

986-
if t.chatty {
987-
// Print directly to root's io.Writer so there is no delay.
988-
root := t.parent
989-
for ; root.parent != nil; root = root.parent {
990-
}
991-
root.mu.Lock()
994+
if t.chatty != nil {
992995
// Unfortunately, even though PAUSE indicates that the named test is *no
993996
// longer* running, cmd/test2json interprets it as changing the active test
994997
// for the purpose of log parsing. We could fix cmd/test2json, but that
995998
// won't fix existing deployments of third-party tools that already shell
996999
// out to older builds of cmd/test2json — so merely fixing cmd/test2json
9971000
// isn't enough for now.
998-
printer.Fprint(root.w, t.name, fmt.Sprintf("=== PAUSE %s\n", t.name))
999-
root.mu.Unlock()
1001+
t.chatty.Updatef(t.name, "=== PAUSE %s\n", t.name)
10001002
}
10011003

10021004
t.signal <- true // Release calling test.
10031005
<-t.parent.barrier // Wait for the parent test to complete.
10041006
t.context.waitParallel()
10051007

1006-
if t.chatty {
1007-
// Print directly to root's io.Writer so there is no delay.
1008-
root := t.parent
1009-
for ; root.parent != nil; root = root.parent {
1010-
}
1011-
root.mu.Lock()
1012-
printer.Fprint(root.w, t.name, fmt.Sprintf("=== CONT %s\n", t.name))
1013-
root.mu.Unlock()
1008+
if t.chatty != nil {
1009+
t.chatty.Updatef(t.name, "=== CONT %s\n", t.name)
10141010
}
10151011

10161012
t.start = time.Now()
@@ -1161,14 +1157,8 @@ func (t *T) Run(name string, f func(t *T)) bool {
11611157
}
11621158
t.w = indenter{&t.common}
11631159

1164-
if t.chatty {
1165-
// Print directly to root's io.Writer so there is no delay.
1166-
root := t.parent
1167-
for ; root.parent != nil; root = root.parent {
1168-
}
1169-
root.mu.Lock()
1170-
printer.Fprint(root.w, t.name, fmt.Sprintf("=== RUN %s\n", t.name))
1171-
root.mu.Unlock()
1160+
if t.chatty != nil {
1161+
t.chatty.Updatef(t.name, "=== RUN %s\n", t.name)
11721162
}
11731163
// Instead of reducing the running count of this test before calling the
11741164
// tRunner and increasing it afterwards, we rely on tRunner keeping the
@@ -1333,8 +1323,6 @@ func (m *M) Run() (code int) {
13331323
flag.Parse()
13341324
}
13351325

1336-
printer = newTestPrinter(Verbose())
1337-
13381326
if *parallel < 1 {
13391327
fmt.Fprintln(os.Stderr, "testing: -parallel can only be given a positive integer")
13401328
flag.Usage()
@@ -1379,7 +1367,7 @@ func (t *T) report() {
13791367
format := "--- %s: %s (%s)\n"
13801368
if t.Failed() {
13811369
t.flushToParent(t.name, format, "FAIL", t.name, dstr)
1382-
} else if t.chatty {
1370+
} else if t.chatty != nil {
13831371
if t.Skipped() {
13841372
t.flushToParent(t.name, format, "SKIP", t.name, dstr)
13851373
} else {
@@ -1440,10 +1428,12 @@ func runTests(matchString func(pat, str string) (bool, error), tests []InternalT
14401428
signal: make(chan bool),
14411429
barrier: make(chan bool),
14421430
w: os.Stdout,
1443-
chatty: *chatty,
14441431
},
14451432
context: ctx,
14461433
}
1434+
if Verbose() {
1435+
t.chatty = newChattyPrinter(t.w)
1436+
}
14471437
tRunner(t, func(t *T) {
14481438
for _, test := range tests {
14491439
t.Run(test.Name, test.F)

0 commit comments

Comments
 (0)