cmd/internal/test2json: generate and validate test artifacts

Adds a mechanism for generating test2json test artifacts from and validating them against a real test. If a .test file has a corresponding .src file, TestGolden will now treat the .src file as a script test, executing it and verifying that the output matches the contents of the .test file. Running TestGolden with the -update flag will also regenerate .test files if they have a corresponding .src file.

Capturing the output of the script test in this way required making minor changes to cmd/internal/script/scripttest.

This was motivated by CL 601535 (golang/go#62728). Specifically, testing that CL required adding src/cmd/internal/test2json/testdata/frameescape.test which has a multitude of non-printing characters and thus must be generated by executing `go test`. Using a script test to generate the test file is more reliable than doing it by hand.

Change-Id: I60456700e37e21a42d0514be2ce86dc6df2bccb0
Reviewed-on: https://go-review.googlesource.com/c/go/+/628615
Reviewed-by: Michael Matloob <matloob@golang.org>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Michael Matloob <matloob@google.com>
Reviewed-by: Damien Neil <dneil@google.com>
Auto-Submit: Damien Neil <dneil@google.com>

src/cmd/internal/script/scripttest/run.go

@@ -29,12 +29,9 @@ type ToolReplacement struct {
 	EnvVar          string // env var setting (e.g. "FOO=BAR")
 }
 
-// RunToolScriptTest kicks off a set of script tests runs for
-// a tool of some sort (compiler, linker, etc). The expectation
-// is that we'll be called from the top level cmd/X dir for tool X,
-// and that instead of executing the install tool X we'll use the
-// test binary instead.
-func RunToolScriptTest(t *testing.T, repls []ToolReplacement, scriptsdir string, fixReadme bool) {
+// NewEngine constructs a new [script.Engine] and environment to be used with
+// [RunTests].
+func NewEngine(t *testing.T, repls []ToolReplacement) (*script.Engine, []string) {
 	// Nearly all script tests involve doing builds, so don't
 	// bother here if we don't have "go build".
 	testenv.MustHaveGoBuild(t)
@@ -156,6 +153,23 @@ func RunToolScriptTest(t *testing.T, repls []ToolReplacement, scriptsdir string,
 		Quiet: !testing.Verbose(),
 	}
 
+	return engine, env
+}
+
+// RunToolScriptTest kicks off a set of script tests runs for
+// a tool of some sort (compiler, linker, etc). The expectation
+// is that we'll be called from the top level cmd/X dir for tool X,
+// and that instead of executing the install tool X we'll use the
+// test binary instead.
+func RunToolScriptTest(t *testing.T, repls []ToolReplacement, scriptsdir string, fixReadme bool) {
+	// Locate our Go tool.
+	gotool, err := testenv.GoTool()
+	if err != nil {
+		t.Fatalf("locating go tool: %v", err)
+	}
+
+	engine, env := NewEngine(t, repls)
+
 	t.Run("README", func(t *testing.T) {
 		checkScriptReadme(t, engine, env, scriptsdir, gotool, fixReadme)
 	})
@@ -166,36 +180,46 @@ func RunToolScriptTest(t *testing.T, repls []ToolReplacement, scriptsdir string,
 	RunTests(t, ctx, engine, env, pattern)
 }
 
+// ScriptTestContext returns a context with a grace period for cleaning up
+// subprocesses of a script test.
+//
+// When we run commands that execute subprocesses, we want to reserve two grace
+// periods to clean up. We will send the first termination signal when the
+// context expires, then wait one grace period for the process to produce
+// whatever useful output it can (such as a stack trace). After the first grace
+// period expires, we'll escalate to os.Kill, leaving the second grace period
+// for the test function to record its output before the test process itself
+// terminates.
+//
+// The grace period is 100ms or 5% of the time remaining until
+// [testing.T.Deadline], whichever is greater.
+func ScriptTestContext(t *testing.T, ctx context.Context) context.Context {
+	deadline, ok := t.Deadline()
+	if !ok {
+		return ctx
+	}
+
+	gracePeriod := 100 * time.Millisecond
+	timeout := time.Until(deadline)
+
+	// If time allows, increase the termination grace period to 5% of the
+	// remaining time.
+	gracePeriod = max(gracePeriod, timeout/20)
+
+	// Reserve two grace periods to clean up
+	timeout -= 2 * gracePeriod
+
+	ctx, cancel := context.WithTimeout(ctx, timeout)
+	t.Cleanup(cancel)
+	return ctx
+}
+
 // RunTests kicks off one or more script-based tests using the
 // specified engine, running all test files that match pattern.
 // This function adapted from Russ's rsc.io/script/scripttest#Run
 // function, which was in turn forked off cmd/go's runner.
 func RunTests(t *testing.T, ctx context.Context, engine *script.Engine, env []string, pattern string) {
-	gracePeriod := 100 * time.Millisecond
-	if deadline, ok := t.Deadline(); ok {
-		timeout := time.Until(deadline)
-
-		// If time allows, increase the termination grace period to 5% of the
-		// remaining time.
-		if gp := timeout / 20; gp > gracePeriod {
-			gracePeriod = gp
-		}
-
-		// When we run commands that execute subprocesses, we want to
-		// reserve two grace periods to clean up. We will send the
-		// first termination signal when the context expires, then
-		// wait one grace period for the process to produce whatever
-		// useful output it can (such as a stack trace). After the
-		// first grace period expires, we'll escalate to os.Kill,
-		// leaving the second grace period for the test function to
-		// record its output before the test process itself
-		// terminates.
-		timeout -= 2 * gracePeriod
-
-		var cancel context.CancelFunc
-		ctx, cancel = context.WithTimeout(ctx, timeout)
-		t.Cleanup(cancel)
-	}
+	ctx = ScriptTestContext(t, ctx)
 
 	files, _ := filepath.Glob(pattern)
 	if len(files) == 0 {
@@ -218,7 +242,7 @@ func RunTests(t *testing.T, ctx context.Context, engine *script.Engine, env []st
 			if err != nil {
 				t.Fatal(err)
 			}
-			initScriptDirs(t, s)
+			InitScriptDirs(t, s)
 			if err := s.ExtractFiles(a); err != nil {
 				t.Fatal(err)
 			}
@@ -237,7 +261,12 @@ func RunTests(t *testing.T, ctx context.Context, engine *script.Engine, env []st
 	}
 }
 
-func initScriptDirs(t testing.TB, s *script.State) {
+// InitScriptDirs sets up directories for executing a script test.
+//
+//   - WORK (env var) is set to the current working directory.
+//   - TMPDIR (env var; TMP on Windows) is set to $WORK/tmp.
+//   - $TMPDIR is created.
+func InitScriptDirs(t testing.TB, s *script.State) {
 	must := func(err error) {
 		if err != nil {
 			t.Helper()

src/cmd/internal/script/scripttest/scripttest.go

@@ -89,7 +89,7 @@ func Run(t testing.TB, e *script.Engine, s *script.State, filename string, testS
 		return e.Execute(s, filename, bufio.NewReader(testScript), log)
 	}()
 
-	if skip, ok := errors.AsType[skipError](err); ok {
+	if skip, ok := errors.AsType[SkipError](err); ok {
 		if skip.msg == "" {
 			t.Skip("SKIP")
 		} else {
@@ -113,17 +113,18 @@ func Skip() script.Cmd {
 				return nil, script.ErrUsage
 			}
 			if len(args) == 0 {
-				return nil, skipError{""}
+				return nil, SkipError{""}
 			}
-			return nil, skipError{args[0]}
+			return nil, SkipError{args[0]}
 		})
 }
 
-type skipError struct {
+// SkipError is returned by a script test that executes the [Skip] command.
+type SkipError struct {
 	msg string
 }
 
-func (s skipError) Error() string {
+func (s SkipError) Error() string {
 	if s.msg == "" {
 		return "skip"
 	}

src/cmd/internal/test2json/test2json_test.go

@@ -5,14 +5,22 @@
 package test2json
 
 import (
+	"bufio"
 	"bytes"
+	"cmd/internal/script"
+	"cmd/internal/script/scripttest"
+	"context"
 	"encoding/json"
+	"errors"
 	"flag"
 	"fmt"
+	"internal/txtar"
 	"io"
+	"io/fs"
 	"os"
 	"path/filepath"
 	"reflect"
+	"regexp"
 	"strings"
 	"testing"
 	"unicode/utf8"
@@ -21,6 +29,8 @@ import (
 var update = flag.Bool("update", false, "rewrite testdata/*.json files")
 
 func TestGolden(t *testing.T) {
+	ctx := scripttest.ScriptTestContext(t, context.Background())
+	engine, env := scripttest.NewEngine(t, nil)
 	files, err := filepath.Glob("testdata/*.test")
 	if err != nil {
 		t.Fatal(err)
@@ -33,6 +43,29 @@ func TestGolden(t *testing.T) {
 				t.Fatal(err)
 			}
 
+			// If there's a corresponding *.src script, execute it
+			srcFile := strings.TrimSuffix(file, ".test") + ".src"
+			if st, err := os.Stat(srcFile); err != nil {
+				if !errors.Is(err, fs.ErrNotExist) {
+					t.Fatal(err)
+				}
+			} else if !st.IsDir() {
+				t.Run("go test", func(t *testing.T) {
+					stdout := runTest(t, ctx, engine, env, srcFile)
+
+					if *update {
+						t.Logf("rewriting %s", file)
+						if err := os.WriteFile(file, []byte(stdout), 0666); err != nil {
+							t.Fatal(err)
+						}
+						orig = []byte(stdout)
+						return
+					}
+
+					diffRaw(t, []byte(stdout), orig)
+				})
+			}
+
 			// Test one line written to c at a time.
 			// Assume that's the most likely to be handled correctly.
 			var buf bytes.Buffer
@@ -141,6 +174,78 @@ func TestGolden(t *testing.T) {
 	}
 }
 
+func runTest(t *testing.T, ctx context.Context, engine *script.Engine, env []string, srcFile string) string {
+	workdir := t.TempDir()
+	s, err := script.NewState(ctx, workdir, env)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	// Unpack archive.
+	a, err := txtar.ParseFile(srcFile)
+	if err != nil {
+		t.Fatal(err)
+	}
+	scripttest.InitScriptDirs(t, s)
+	if err := s.ExtractFiles(a); err != nil {
+		t.Fatal(err)
+	}
+
+	err, stdout := func() (err error, stdout string) {
+		log := new(strings.Builder)
+
+		// Defer writing to the test log in case the script engine panics during execution,
+		// but write the log before we write the final "skip" or "FAIL" line.
+		t.Helper()
+		defer func() {
+			t.Helper()
+
+			stdout = s.Stdout()
+			if closeErr := s.CloseAndWait(log); err == nil {
+				err = closeErr
+			}
+
+			if log.Len() > 0 && (testing.Verbose() || err != nil) {
+				t.Log(strings.TrimSuffix(log.String(), "\n"))
+			}
+		}()
+
+		if testing.Verbose() {
+			// Add the environment to the start of the script log.
+			wait, err := script.Env().Run(s)
+			if err != nil {
+				t.Fatal(err)
+			}
+			if wait != nil {
+				stdout, stderr, err := wait(s)
+				if err != nil {
+					t.Fatalf("env: %v\n%s", err, stderr)
+				}
+				if len(stdout) > 0 {
+					s.Logf("%s\n", stdout)
+				}
+			}
+		}
+
+		testScript := bytes.NewReader(a.Comment)
+		err = engine.Execute(s, srcFile, bufio.NewReader(testScript), log)
+		return
+	}()
+	if skip := (scripttest.SkipError{}); errors.As(err, &skip) {
+		t.Skipf("SKIP: %v", skip)
+	} else if err != nil {
+		t.Fatalf("FAIL: %v", err)
+	}
+
+	// Remove the output after "=== NAME"
+	i := strings.LastIndex(stdout, "\n\x16=== NAME")
+	if i >= 0 {
+		stdout = stdout[:i+1]
+	}
+
+	return stdout
+}
+
 // writeAndKill writes b to w and then fills b with Zs.
 // The filling makes sure that if w is holding onto b for
 // future use, that future use will have obviously wrong data.
@@ -271,6 +376,56 @@ func diffJSON(t *testing.T, have, want []byte) {
 	}
 }
 
+var reRuntime = regexp.MustCompile(`\d*\.\d*s`)
+
+func diffRaw(t *testing.T, have, want []byte) {
+	have = bytes.TrimSpace(have)
+	want = bytes.TrimSpace(want)
+
+	// Replace durations (e.g. 0.01s) with a placeholder
+	have = reRuntime.ReplaceAll(have, []byte("X.XXs"))
+	want = reRuntime.ReplaceAll(want, []byte("X.XXs"))
+
+	// Compare
+	if bytes.Equal(have, want) {
+		return
+	}
+
+	// Escape non-printing characters to make the error more legible
+	have = escapeNonPrinting(have)
+	want = escapeNonPrinting(want)
+
+	// Find where the output differs and remember the last newline
+	var i, nl int
+	for i < len(have) && i < len(want) && have[i] == want[i] {
+		if have[i] == '\n' {
+			nl = i
+		}
+	}
+
+	if nl == 0 {
+		t.Fatalf("\nhave:\n%s\nwant:\n%s", have, want)
+	} else {
+		nl++
+		t.Fatalf("\nhave:\n%s» %s\nwant:\n%s» %s", have[:nl], have[nl:], want[:nl], want[nl:])
+	}
+}
+
+func escapeNonPrinting(buf []byte) []byte {
+	for i := 0; i < len(buf); i++ {
+		c := buf[i]
+		if 0x20 <= c && c < 0x7F || c > 0x7F || c == '\n' {
+			continue
+		}
+		escaped := fmt.Sprintf(`\x%02x`, c)
+		buf = append(buf[:i+len(escaped)], buf[i+1:]...)
+		for j := 0; j < len(escaped); j++ {
+			buf[i+j] = escaped[j]
+		}
+	}
+	return buf
+}
+
 func TestTrimUTF8(t *testing.T) {
 	s := "hello α ☺ 😂 world" // α is 2-byte, ☺ is 3-byte, 😂 is 4-byte
 	b := []byte(s)

src/cmd/internal/test2json/testdata/README.md

@@ -0,0 +1,11 @@
+# test2json test artifacts
+
+This directory contains test artifacts for `TestGolden` in
+[test2json_test.go](../test2json_test.go). For each set of `<test>.*` files:
+
+- If `<test>.src` is present, TestGolden executes it as a script test and verifies
+  that the output matches `<test>.test`. This verifies that the testing package
+  produces the output expected by test2json.
+- TestGolden reads `<test>.test` and processes it with a `Converter`, verifying
+  that the output matches `<test>.json`.This verifies that test2json produces
+  the expected output events.

src/cmd/internal/test2json/testdata/frameescape.src

@@ -0,0 +1,24 @@
+! go test -v=test2json
+
+stdout '=== RUN   TestAscii'
+
+-- go.mod --
+module p
+
+-- x_test.go --
+package p
+
+import "testing"
+
+func TestAscii(t *testing.T) {
+	t.Run("Log", func(t *testing.T) {
+		for i := rune(0); i < 0x80; i++ {
+			t.Log(string(i))
+		}
+	})
+	t.Run("Error", func(t *testing.T) {
+		for i := rune(0); i < 0x80; i++ {
+			t.Error(string(i))
+		}
+	})
+}

src/cmd/internal/test2json/testdata/multiline-error.src

@@ -0,0 +1,15 @@
+! go test -v=test2json
+
+stdout '=== RUN   Test'
+
+-- go.mod --
+module p
+
+-- x_test.go --
+package p
+
+import "testing"
+
+func Test(t *testing.T) {
+	t.Error("Error1\nError2\r")
+}