]> Cypherpunks repositories - gostls13.git/commitdiff
cmd/go: print test2json start events
authorRuss Cox <rsc@golang.org>
Mon, 7 Nov 2022 16:58:45 +0000 (11:58 -0500)
committerGopher Robot <gobot@golang.org>
Wed, 9 Nov 2022 17:33:07 +0000 (17:33 +0000)
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 <rsc@golang.org>
Auto-Submit: Russ Cox <rsc@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
20 files changed:
src/cmd/go/internal/test/test.go
src/cmd/go/testdata/script/test_json.txt
src/cmd/internal/test2json/test2json.go
src/cmd/internal/test2json/testdata/ascii.json
src/cmd/internal/test2json/testdata/bench.json
src/cmd/internal/test2json/testdata/benchfail.json
src/cmd/internal/test2json/testdata/benchshort.json
src/cmd/internal/test2json/testdata/empty.json
src/cmd/internal/test2json/testdata/frame.json
src/cmd/internal/test2json/testdata/framebig.json
src/cmd/internal/test2json/testdata/framefuzz.json
src/cmd/internal/test2json/testdata/issue23036.json
src/cmd/internal/test2json/testdata/issue23920.json
src/cmd/internal/test2json/testdata/issue29755.json
src/cmd/internal/test2json/testdata/panic.json
src/cmd/internal/test2json/testdata/smiley.json
src/cmd/internal/test2json/testdata/timeout.json
src/cmd/internal/test2json/testdata/unicode.json
src/cmd/internal/test2json/testdata/vet.json
src/cmd/test2json/main.go

index 86b66c226f447cdde75e45b2861009520e1cd5f9..6ec32dfa1e4b8c1ba1336bbeeedb230ac864c62f 100644 (file)
@@ -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
index f2bee34ce2c8d2bbcdb6a779785ecd203e9d345c..6207c2efd43d711f87296211fe05503600d2b326 100644 (file)
@@ -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\)'
index 807dcc510206d802b8031a596914ea429b5ef518..f7dfbe69d7725c9bb12ddda16684f0f2c7cb053e 100644 (file)
@@ -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"
        }
index 67fccfc11212e760f17f51760567020129e9970f..94695a10c5541ef57ddb4fe6e66c4e96b65f4e8b 100644 (file)
@@ -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"}
index 69e417eb144999f9300cec0e947652734608fd13..102e189ed7ad3ca2746fa65eef98a753564437e0 100644 (file)
@@ -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"}
index ad3ac9e179a0011cd0024b061e6ca4b947df7122..d2d968191c4ffc8f9f7ea9c6773f4f4b440ea041 100644 (file)
@@ -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"}
index 34b03b9362fa42a7502a33935744a10edb1525a5..6c4e19357393246726e38e9831675db9dc7ef658 100644 (file)
@@ -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"}
index e69de29bb2d1d6434b8b29ae775ad8c2e48c5391..198f8d7b55384e7190a2d90b923d5fe9be39ceb1 100644 (file)
@@ -0,0 +1 @@
+{"Action":"start"}
index d2a65fc36bd66449e9f1272c8206d19d5143828e..9dd29ae97758b4c1e41fb75f11e8cd411ef37d8a 100644 (file)
@@ -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"}
index ebb9bdf3f179a42cf4ac522eea3c1dc0cc0e0e66..54a8a524fe4708a733d62ae60b33438e764ee635 100644 (file)
@@ -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"}
index ea2eafa717f20c5493ee30cc3449e65aa52d397e..25869ee7408d5b82ec34e25388f5f44041c45eff 100644 (file)
@@ -1,3 +1,4 @@
+{"Action":"start"}
 {"Action":"run","Test":"TestAddrStringAllocs"}
 {"Action":"output","Test":"TestAddrStringAllocs","Output":"=== RUN   TestAddrStringAllocs\n"}
 {"Action":"run","Test":"TestAddrStringAllocs/zero"}
index 935c0c5fc0e9c945ca6648efaf8dbf871f330a37..bfdc3e5e0f8fd44aac0402487b59303a4dfdbfbf 100644 (file)
@@ -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"}
index 28f7bd56ac39fb62bb24e967a8d3b1f27d00e9d8..17e8de6e917c663e249c59597ac695e21ef72bac 100644 (file)
@@ -1,3 +1,4 @@
+{"Action":"start"}
 {"Action":"run","Test":"TestWithColons"}
 {"Action":"output","Test":"TestWithColons","Output":"=== RUN   TestWithColons\n"}
 {"Action":"run","Test":"TestWithColons/[::1]"}
index 2e8ba48629d7a315d8366a867c986cdbc52b82d9..c49bf92ce2a49a86f6143281f611945a1bc438ae 100644 (file)
@@ -1,3 +1,4 @@
+{"Action":"start"}
 {"Action":"run","Test":"TestOutputWithSubtest"}
 {"Action":"output","Test":"TestOutputWithSubtest","Output":"=== RUN   TestOutputWithSubtest\n"}
 {"Action":"run","Test":"TestOutputWithSubtest/sub_test"}
index f7738142e60adc389ec413b2605890188c2f4482..1cd43846298b5cc2e970f9476300ffcbf3bddc2b 100644 (file)
@@ -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"}
index f49180d52074ae5331482977d0d1a576527c5dfe..858843f3af2174b8fa2c9d52ccf611dace9b06a8 100644 (file)
@@ -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"}
index 162a5bde4492c5ab6259529faf9ba038728a5bb2..dc225262f7c3263f88c8e37db10eba6cc868dd29 100644 (file)
@@ -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"}
index 9cfb5f2d498d1cf45573920d9d0abb5c9faf8e05..2cc3e7322ddf486078164117c879127842de911d 100644 (file)
@@ -1,3 +1,4 @@
+{"Action":"start"}
 {"Action":"run","Test":"TestUnicode"}
 {"Action":"output","Test":"TestUnicode","Output":"=== RUN   TestUnicode\n"}
 {"Action":"output","Test":"TestUnicode","Output":"Μπορώ να φάω σπασμένα γυαλιά χωρίς να πάθω τίποτα. Μπορώ να φάω σπασμένα γυαλιά χωρίς να πάθω τίποτα.\n"}
index 2558d61e7471ab5e99de6391ca793e65f9e4bb19..5b09104522af94af01d0224d58c5de043700314b 100644 (file)
@@ -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"}
index 06648b1a9cb3b4230924aa1dd78e830ccb8c747e..09d5fcec79cb499c8b239ffe7fae7154b9edffef 100644 (file)
@@ -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