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>

20 files changed, 90 insertions, 28 deletions

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