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 <rsc@golang.org>
Auto-Submit: Russ Cox <rsc@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>

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

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\)'

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"
 	}

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"}

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"}

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"}

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"}

src/cmd/internal/test2json/testdata/empty.json

@@ -0,0 +1 @@
+{"Action":"start"}

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"}

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"}

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"}

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"}

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]"}

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"}

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"}

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"}

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"}

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"}

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"}

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