From: Russ Cox Date: Mon, 7 Nov 2022 16:58:45 +0000 (-0500) Subject: cmd/go: print test2json start events X-Git-Tag: go1.20rc1~358 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=7a92c4fc637621368eb26a7e72bb027b29568e50;p=gostls13.git cmd/go: print test2json start events Add a new "Action":"start" test2json event to mark the start of the test binary execution. This adds useful information to the JSON traces, and it also lets programs watching test execution see the order in which the tests are being run, because we arrange for the starts to happen sequentially. Change-Id: I9fc865a486a55a7e9315f8686f59a2aa06455884 Reviewed-on: https://go-review.googlesource.com/c/go/+/448357 Run-TryBot: Russ Cox Auto-Submit: Russ Cox TryBot-Result: Gopher Robot Reviewed-by: Bryan Mills --- diff --git a/src/cmd/go/internal/test/test.go b/src/cmd/go/internal/test/test.go index 86b66c226f..6ec32dfa1e 100644 --- a/src/cmd/go/internal/test/test.go +++ b/src/cmd/go/internal/test/test.go @@ -847,6 +847,17 @@ func runTest(ctx context.Context, cmd *base.Command, args []string) { prints = append(prints, printTest) } + // Order runs for coordinating start JSON prints. + ch := make(chan struct{}) + close(ch) + for _, a := range runs { + if r, ok := a.Actor.(*runTestActor); ok { + r.prev = ch + ch = make(chan struct{}) + r.next = ch + } + } + // Ultimately the goal is to print the output. root := &work.Action{Mode: "go test", Actor: work.ActorFunc(printExitStatus), Deps: prints} @@ -884,9 +895,21 @@ var windowsBadWords = []string{ func builderTest(b *work.Builder, ctx context.Context, pkgOpts load.PackageOpts, p *load.Package, imported bool) (buildAction, runAction, printAction *work.Action, err error) { if len(p.TestGoFiles)+len(p.XTestGoFiles) == 0 { build := b.CompileAction(work.ModeBuild, work.ModeBuild, p) - run := &work.Action{Mode: "test run", Package: p, Deps: []*work.Action{build}} + run := &work.Action{ + Mode: "test run", + Actor: new(runTestActor), + Deps: []*work.Action{build}, + Package: p, + IgnoreFail: true, // run (prepare output) even if build failed + } addTestVet(b, p, run, nil) - print := &work.Action{Mode: "test print", Actor: work.ActorFunc(builderNoTest), Package: p, Deps: []*work.Action{run}} + print := &work.Action{ + Mode: "test print", + Actor: work.ActorFunc(builderPrintTest), + Deps: []*work.Action{run}, + Package: p, + IgnoreFail: true, // print even if test failed + } return build, run, print, nil } @@ -1013,14 +1036,14 @@ func builderTest(b *work.Builder, ctx context.Context, pkgOpts load.PackageOpts, vetRunAction = printAction } else { // run test - c := new(runCache) + r := new(runTestActor) runAction = &work.Action{ Mode: "test run", - Actor: work.ActorFunc(c.builderRunTest), + Actor: r, Deps: []*work.Action{buildAction}, Package: p, IgnoreFail: true, // run (prepare output) even if build failed - TryCache: c.tryCache, + TryCache: r.c.tryCache, Objdir: testDir, } vetRunAction = runAction @@ -1080,6 +1103,16 @@ var noTestsToRun = []byte("\ntesting: warning: no tests to run\n") var noFuzzTestsToFuzz = []byte("\ntesting: warning: no fuzz tests to fuzz\n") var tooManyFuzzTestsToFuzz = []byte("\ntesting: warning: -fuzz matches more than one fuzz test, won't fuzz\n") +// runTestActor is the actor for running a test. +type runTestActor struct { + c runCache + + // sequencing of json start messages, to preserve test order + prev <-chan struct{} // wait to start until prev is closed + next chan<- struct{} // close next once the next test can start. +} + +// runCache is the cache for running a single test. type runCache struct { disableCache bool // cache should be disabled for this run @@ -1103,14 +1136,19 @@ func (lockedStdout) Write(b []byte) (int, error) { return os.Stdout.Write(b) } -// builderRunTest is the action for running a test binary. -func (c *runCache) builderRunTest(b *work.Builder, ctx context.Context, a *work.Action) error { +func (r *runTestActor) Act(b *work.Builder, ctx context.Context, a *work.Action) error { + // Wait for previous test to get started and print its first json line. + <-r.prev + if a.Failed { // We were unable to build the binary. a.Failed = false a.TestOutput = new(bytes.Buffer) fmt.Fprintf(a.TestOutput, "FAIL\t%s [build failed]\n", a.Package.ImportPath) base.SetExitStatus(1) + + // release next test to start + close(r.next) return nil } @@ -1125,6 +1163,14 @@ func (c *runCache) builderRunTest(b *work.Builder, ctx context.Context, a *work. stdout = json } + // Release next test to start (test2json.NewConverter writes the start event). + close(r.next) + + if p := a.Package; len(p.TestGoFiles)+len(p.XTestGoFiles) == 0 { + fmt.Fprintf(stdout, "? \t%s\t[no test files]\n", p.ImportPath) + return nil + } + var buf bytes.Buffer if len(pkgArgs) == 0 || testBench != "" || testFuzz != "" { // Stream test output (no buffering) when no package has @@ -1155,7 +1201,7 @@ func (c *runCache) builderRunTest(b *work.Builder, ctx context.Context, a *work. } } - if c.buf == nil { + if r.c.buf == nil { // We did not find a cached result using the link step action ID, // so we ran the link step. Try again now with the link output // content ID. The attempt using the action ID makes sure that @@ -1165,20 +1211,20 @@ func (c *runCache) builderRunTest(b *work.Builder, ctx context.Context, a *work. // we have different link inputs but the same final binary, // we still reuse the cached test result. // c.saveOutput will store the result under both IDs. - c.tryCacheWithID(b, a, a.Deps[0].BuildContentID()) + r.c.tryCacheWithID(b, a, a.Deps[0].BuildContentID()) } - if c.buf != nil { + if r.c.buf != nil { if stdout != &buf { - stdout.Write(c.buf.Bytes()) - c.buf.Reset() + stdout.Write(r.c.buf.Bytes()) + r.c.buf.Reset() } - a.TestOutput = c.buf + a.TestOutput = r.c.buf return nil } execCmd := work.FindExecCmd() testlogArg := []string{} - if !c.disableCache && len(execCmd) == 0 { + if !r.c.disableCache && len(execCmd) == 0 { testlogArg = []string{"-test.testlogfile=" + a.Objdir + "testlog.txt"} } panicArg := "-test.paniconexit0" @@ -1319,7 +1365,7 @@ func (c *runCache) builderRunTest(b *work.Builder, ctx context.Context, a *work. cmd.Stdout.Write([]byte("\n")) } fmt.Fprintf(cmd.Stdout, "ok \t%s\t%s%s%s\n", a.Package.ImportPath, t, coveragePercentage(out), norun) - c.saveOutput(a) + r.c.saveOutput(a) } else { base.SetExitStatus(1) if len(out) == 0 { @@ -1749,18 +1795,6 @@ func builderPrintTest(b *work.Builder, ctx context.Context, a *work.Action) erro return nil } -// builderNoTest is the action for testing a package with no test files. -func builderNoTest(b *work.Builder, ctx context.Context, a *work.Action) error { - var stdout io.Writer = os.Stdout - if testJSON { - json := test2json.NewConverter(lockedStdout{}, a.Package.ImportPath, test2json.Timestamp) - defer json.Close() - stdout = json - } - fmt.Fprintf(stdout, "? \t%s\t[no test files]\n", a.Package.ImportPath) - return nil -} - // printExitStatus is the action for printing the final exit status. // If we are running multiple test targets, print a final "FAIL" // in case a failure in an early package has already scrolled diff --git a/src/cmd/go/testdata/script/test_json.txt b/src/cmd/go/testdata/script/test_json.txt index f2bee34ce2..6207c2efd4 100644 --- a/src/cmd/go/testdata/script/test_json.txt +++ b/src/cmd/go/testdata/script/test_json.txt @@ -11,16 +11,22 @@ go test -json -short -v errors m/empty/pkg m/skipper # Check errors for run action stdout '"Package":"errors"' +stdout '"Action":"start","Package":"errors"' stdout '"Action":"run","Package":"errors"' # Check m/empty/pkg for output and skip actions +stdout '"Action":"start","Package":"m/empty/pkg"' stdout '"Action":"output","Package":"m/empty/pkg","Output":".*no test files' stdout '"Action":"skip","Package":"m/empty/pkg"' # Check skipper for output and skip actions +stdout '"Action":"start","Package":"m/skipper"' stdout '"Action":"output","Package":"m/skipper","Test":"Test","Output":"--- SKIP:' stdout '"Action":"skip","Package":"m/skipper","Test":"Test"' +# Check that starts were ordered properly. +stdout '(?s)"Action":"start","Package":"errors".*"Action":"start","Package":"m/empty/pkg".*"Action":"start","Package":"m/skipper"' + # Run go test -json on errors and check it's cached go test -json -short -v errors stdout '"Action":"output","Package":"errors","Output":".*\(cached\)' diff --git a/src/cmd/internal/test2json/test2json.go b/src/cmd/internal/test2json/test2json.go index 807dcc5102..f7dfbe69d7 100644 --- a/src/cmd/internal/test2json/test2json.go +++ b/src/cmd/internal/test2json/test2json.go @@ -119,6 +119,7 @@ func NewConverter(w io.Writer, pkg string, mode Mode) *Converter { part: c.writeOutputEvent, }, } + c.writeEvent(&event{Action: "start"}) return c } @@ -131,7 +132,9 @@ func (c *Converter) Write(b []byte) (int, error) { // Exited marks the test process as having exited with the given error. func (c *Converter) Exited(err error) { if err == nil { - c.result = "pass" + if c.result != "skip" { + c.result = "pass" + } } else { c.result = "fail" } diff --git a/src/cmd/internal/test2json/testdata/ascii.json b/src/cmd/internal/test2json/testdata/ascii.json index 67fccfc112..94695a10c5 100644 --- a/src/cmd/internal/test2json/testdata/ascii.json +++ b/src/cmd/internal/test2json/testdata/ascii.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestAscii"} {"Action":"output","Test":"TestAscii","Output":"=== RUN TestAscii\n"} {"Action":"output","Test":"TestAscii","Output":"I can eat glass, and it doesn't hurt me. I can eat glass, and it doesn't hurt me.\n"} diff --git a/src/cmd/internal/test2json/testdata/bench.json b/src/cmd/internal/test2json/testdata/bench.json index 69e417eb14..102e189ed7 100644 --- a/src/cmd/internal/test2json/testdata/bench.json +++ b/src/cmd/internal/test2json/testdata/bench.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"output","Output":"goos: darwin\n"} {"Action":"output","Output":"goarch: 386\n"} {"Action":"output","Output":"BenchmarkFoo-8 \t2000000000\t 0.00 ns/op\n"} diff --git a/src/cmd/internal/test2json/testdata/benchfail.json b/src/cmd/internal/test2json/testdata/benchfail.json index ad3ac9e179..d2d968191c 100644 --- a/src/cmd/internal/test2json/testdata/benchfail.json +++ b/src/cmd/internal/test2json/testdata/benchfail.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"output","Test":"BenchmarkFoo","Output":"--- FAIL: BenchmarkFoo\n"} {"Action":"output","Test":"BenchmarkFoo","Output":"\tx_test.go:8: My benchmark\n"} {"Action":"fail","Test":"BenchmarkFoo"} diff --git a/src/cmd/internal/test2json/testdata/benchshort.json b/src/cmd/internal/test2json/testdata/benchshort.json index 34b03b9362..6c4e193573 100644 --- a/src/cmd/internal/test2json/testdata/benchshort.json +++ b/src/cmd/internal/test2json/testdata/benchshort.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"output","Output":"# This file ends in an early EOF to trigger the Benchmark prefix test,\n"} {"Action":"output","Output":"# which only happens when a benchmark prefix is seen ahead of the \\n.\n"} {"Action":"output","Output":"# Normally that's due to the benchmark running and the \\n coming later,\n"} diff --git a/src/cmd/internal/test2json/testdata/empty.json b/src/cmd/internal/test2json/testdata/empty.json index e69de29bb2..198f8d7b55 100644 --- a/src/cmd/internal/test2json/testdata/empty.json +++ b/src/cmd/internal/test2json/testdata/empty.json @@ -0,0 +1 @@ +{"Action":"start"} diff --git a/src/cmd/internal/test2json/testdata/frame.json b/src/cmd/internal/test2json/testdata/frame.json index d2a65fc36b..9dd29ae977 100644 --- a/src/cmd/internal/test2json/testdata/frame.json +++ b/src/cmd/internal/test2json/testdata/frame.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestAscii"} {"Action":"output","Test":"TestAscii","Output":"=== RUN TestAscii\n"} {"Action":"output","Test":"TestAscii","Output":"=== RUN TestNotReally\n"} diff --git a/src/cmd/internal/test2json/testdata/framebig.json b/src/cmd/internal/test2json/testdata/framebig.json index ebb9bdf3f1..54a8a524fe 100644 --- a/src/cmd/internal/test2json/testdata/framebig.json +++ b/src/cmd/internal/test2json/testdata/framebig.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestIndex"} {"Action":"output","Test":"TestIndex","Output":"=== RUN TestIndex\n"} {"Action":"output","Test":"TestIndex","Output":"--- PASS: TestIndex (0.00s)\n"} diff --git a/src/cmd/internal/test2json/testdata/framefuzz.json b/src/cmd/internal/test2json/testdata/framefuzz.json index ea2eafa717..25869ee740 100644 --- a/src/cmd/internal/test2json/testdata/framefuzz.json +++ b/src/cmd/internal/test2json/testdata/framefuzz.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestAddrStringAllocs"} {"Action":"output","Test":"TestAddrStringAllocs","Output":"=== RUN TestAddrStringAllocs\n"} {"Action":"run","Test":"TestAddrStringAllocs/zero"} diff --git a/src/cmd/internal/test2json/testdata/issue23036.json b/src/cmd/internal/test2json/testdata/issue23036.json index 935c0c5fc0..bfdc3e5e0f 100644 --- a/src/cmd/internal/test2json/testdata/issue23036.json +++ b/src/cmd/internal/test2json/testdata/issue23036.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestActualCase"} {"Action":"output","Test":"TestActualCase","Output":"=== RUN TestActualCase\n"} {"Action":"output","Test":"TestActualCase","Output":"--- FAIL: TestActualCase (0.00s)\n"} diff --git a/src/cmd/internal/test2json/testdata/issue23920.json b/src/cmd/internal/test2json/testdata/issue23920.json index 28f7bd56ac..17e8de6e91 100644 --- a/src/cmd/internal/test2json/testdata/issue23920.json +++ b/src/cmd/internal/test2json/testdata/issue23920.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestWithColons"} {"Action":"output","Test":"TestWithColons","Output":"=== RUN TestWithColons\n"} {"Action":"run","Test":"TestWithColons/[::1]"} diff --git a/src/cmd/internal/test2json/testdata/issue29755.json b/src/cmd/internal/test2json/testdata/issue29755.json index 2e8ba48629..c49bf92ce2 100644 --- a/src/cmd/internal/test2json/testdata/issue29755.json +++ b/src/cmd/internal/test2json/testdata/issue29755.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestOutputWithSubtest"} {"Action":"output","Test":"TestOutputWithSubtest","Output":"=== RUN TestOutputWithSubtest\n"} {"Action":"run","Test":"TestOutputWithSubtest/sub_test"} diff --git a/src/cmd/internal/test2json/testdata/panic.json b/src/cmd/internal/test2json/testdata/panic.json index f7738142e6..1cd4384629 100644 --- a/src/cmd/internal/test2json/testdata/panic.json +++ b/src/cmd/internal/test2json/testdata/panic.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"output","Test":"TestPanic","Output":"--- FAIL: TestPanic (0.00s)\n"} {"Action":"output","Test":"TestPanic","Output":"panic: oops [recovered]\n"} {"Action":"output","Test":"TestPanic","Output":"\tpanic: oops\n"} diff --git a/src/cmd/internal/test2json/testdata/smiley.json b/src/cmd/internal/test2json/testdata/smiley.json index f49180d520..858843f3af 100644 --- a/src/cmd/internal/test2json/testdata/smiley.json +++ b/src/cmd/internal/test2json/testdata/smiley.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"Test☺☹"} {"Action":"output","Test":"Test☺☹","Output":"=== RUN Test☺☹\n"} {"Action":"output","Test":"Test☺☹","Output":"=== PAUSE Test☺☹\n"} diff --git a/src/cmd/internal/test2json/testdata/timeout.json b/src/cmd/internal/test2json/testdata/timeout.json index 162a5bde44..dc225262f7 100644 --- a/src/cmd/internal/test2json/testdata/timeout.json +++ b/src/cmd/internal/test2json/testdata/timeout.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"Test"} {"Action":"output","Test":"Test","Output":"=== RUN Test\n"} {"Action":"output","Test":"Test","Output":"panic: test timed out after 1s\n"} diff --git a/src/cmd/internal/test2json/testdata/unicode.json b/src/cmd/internal/test2json/testdata/unicode.json index 9cfb5f2d49..2cc3e7322d 100644 --- a/src/cmd/internal/test2json/testdata/unicode.json +++ b/src/cmd/internal/test2json/testdata/unicode.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestUnicode"} {"Action":"output","Test":"TestUnicode","Output":"=== RUN TestUnicode\n"} {"Action":"output","Test":"TestUnicode","Output":"Μπορώ να φάω σπασμένα γυαλιά χωρίς να πάθω τίποτα. Μπορώ να φάω σπασμένα γυαλιά χωρίς να πάθω τίποτα.\n"} diff --git a/src/cmd/internal/test2json/testdata/vet.json b/src/cmd/internal/test2json/testdata/vet.json index 2558d61e74..5b09104522 100644 --- a/src/cmd/internal/test2json/testdata/vet.json +++ b/src/cmd/internal/test2json/testdata/vet.json @@ -1,3 +1,4 @@ +{"Action":"start"} {"Action":"run","Test":"TestVet"} {"Action":"output","Test":"TestVet","Output":"=== RUN TestVet\n"} {"Action":"output","Test":"TestVet","Output":"=== PAUSE TestVet\n"} diff --git a/src/cmd/test2json/main.go b/src/cmd/test2json/main.go index 06648b1a9c..09d5fcec79 100644 --- a/src/cmd/test2json/main.go +++ b/src/cmd/test2json/main.go @@ -48,6 +48,7 @@ // // The Action field is one of a fixed set of action descriptions: // +// start - the test binary is about to be executed // run - the test has started running // pause - the test has been paused // cont - the test has continued running @@ -57,6 +58,8 @@ // output - the test printed output // skip - the test was skipped or the package contained no tests // +// Every JSON stream begins with a "start" event. +// // The Package field, if present, specifies the package being tested. // When the go command runs parallel tests in -json mode, events from // different tests are interlaced; the Package field allows readers to