qbit/go
1
0
Fork 0
mirror of https://github.com/golang/go synced 2024-11-23 10:20:03 -07:00
Code Releases Activity

testing: flush test summaries to stdout atomically when streaming output

Browse Source 
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>
This commit is contained in:
Bryan C. Mills 2020-08-18 22:47:12 -04:00
parent e6583dc953
commit 51c0bdc6d1
3 changed files with 89 additions and 88 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

18
src/testing/benchmark.go
View File

@ -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)

19
src/testing/sub_test.go
View File

@ -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)

140
src/testing/testing.go
View File

@ -327,7 +327,6 @@ var (
cpuListStr *string
parallel *int
testlog *string
printer *testPrinter
haveExamples bool // are there examples?
@ -337,55 +336,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
@ -407,12 +396,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.
@ -574,12 +563,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 {
@ -748,13 +756,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
@ -1003,34 +1011,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()
@ -1181,14 +1177,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
@ -1355,8 +1345,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()
@ -1401,7 +1389,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 {
@ -1462,10 +1450,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)