testing: fix many test2json inaccuracies

Test2json is parsing the output stream from the test, which includes
package testing's own framing lines intermingled with other output,
in particular any output printed via fmt.Printf, println, and so on.
We have had recurring problems with unexpected partial output lines
causing a framing line to be missed.

A recent talk at GopherCon gave an example of an integration test
involving Docker that happened to print \r-terminated lines instead
of \n-terminated lines in some configurations, which in turn broke
test2json badly. (https://www.gophercon.com/agenda/session/944259)

There are also a variety of open reported issues with similar problems,
which this CL also addresses. The general approach is to add a new
testing flag -test.v=json that means to print additional output to help
test2json. And then test2json takes advantage of that output.

Among the fixes:

 - Identify testing framing more reliably, using ^V
   (#23036, #26325, #43683, GopherCon talk)
 - Test that output with \r\n endings is handled correctly
   (#43683, #34286)
 - Use === RUN in fuzz tests (#52636, #48132)
 - Add === RUN lines to note benchmark starts (#27764, #49505)
 - Print subtest --- PASS/FAIL lines as they happen (#29811)
 - Add === NAME lines to emit more test change events,
   such as when a subtest stops and the parent continues running.
 - Fix event shown in overall test failure (#27568)
 - Avoid interleaving of writes to os.Stdout and os.Stderr (#33419)

Fixes #23036.
Fixes #26325.
Fixes #27568.
Fixes #27764.
Fixes #29811.
Fixes #33419.
Fixes #34286.
Fixes #43683.
Fixes #49505.
Fixes #52636.

Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6
Reviewed-on: https://go-review.googlesource.com/c/go/+/443596
Auto-Submit: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>

1 files changed, 124 insertions, 27 deletions

diff --git a/src/testing/testing.go b/src/testing/testing.go
index c7d51a13e3..76dcc1ab73 100644
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -418,7 +418,7 @@ func Init() {
 	// the "go test" command is run.
 	outputDir = flag.String("test.outputdir", "", "write profiles to `dir`")
 	// Report as tests are run; default is silent for success.
-	chatty = flag.Bool("test.v", false, "verbose: print additional output")
+	flag.Var(&chatty, "test.v", "verbose: print additional output")
 	count = flag.Uint("test.count", 1, "run tests and benchmarks `n` times")
 	coverProfile = flag.String("test.coverprofile", "", "write a coverage profile to `file`")
 	gocoverdir = flag.String("test.gocoverdir", "", "write coverage intermediate files to this directory")
@@ -449,7 +449,7 @@ var (
 	short                *bool
 	failFast             *bool
 	outputDir            *string
-	chatty               *bool
+	chatty               chattyFlag
 	count                *uint
 	coverProfile         *string
 	gocoverdir           *string
@@ -479,14 +479,66 @@ var (
 	numFailed atomic.Uint32 // number of test failures
 )
 
+type chattyFlag struct {
+	on   bool // -v is set in some form
+	json bool // -v=test2json is set, to make output better for test2json
+}
+
+func (*chattyFlag) IsBoolFlag() bool { return true }
+
+func (f *chattyFlag) Set(arg string) error {
+	switch arg {
+	default:
+		return fmt.Errorf("invalid flag -test.v=%s", arg)
+	case "true", "test2json":
+		f.on = true
+		f.json = arg == "test2json"
+	case "false":
+		f.on = false
+		f.json = false
+	}
+	return nil
+}
+
+func (f *chattyFlag) String() string {
+	if f.json {
+		return "test2json"
+	}
+	if f.on {
+		return "true"
+	}
+	return "false"
+}
+
+const marker = byte(0x16) // ^V for framing
+
+func (f *chattyFlag) prefix() string {
+	if f.json {
+		return string(marker)
+	}
+	return ""
+}
+
 type chattyPrinter struct {
 	w          io.Writer
 	lastNameMu sync.Mutex // guards lastName
 	lastName   string     // last printed test name in chatty mode
+	json       bool       // -v=json output mode
 }
 
 func newChattyPrinter(w io.Writer) *chattyPrinter {
-	return &chattyPrinter{w: w}
+	return &chattyPrinter{w: w, json: chatty.json}
+}
+
+// prefix is like chatty.prefix but using p.json instead of chatty.json.
+// Using p.json allows tests to check the json behavior without modifying
+// the global variable. For convenience, we allow p == nil and treat
+// that as not in json mode (because it's not chatty at all).
+func (p *chattyPrinter) prefix() string {
+	if p != nil && p.json {
+		return string(marker)
+	}
+	return ""
 }
 
 // Updatef prints a message about the status of the named test to w.
@@ -497,11 +549,11 @@ func (p *chattyPrinter) Updatef(testName, format string, args ...any) {
 	defer p.lastNameMu.Unlock()
 
 	// Since the message already implies an association with a specific new test,
-	// we don't need to check what the old test name was or log an extra CONT line
+	// we don't need to check what the old test name was or log an extra NAME line
 	// for it. (We're updating it anyway, and the current message already includes
 	// the test name.)
 	p.lastName = testName
-	fmt.Fprintf(p.w, format, args...)
+	fmt.Fprintf(p.w, p.prefix()+format, args...)
 }
 
 // Printf prints a message, generated by the named test, that does not
@@ -513,7 +565,7 @@ func (p *chattyPrinter) Printf(testName, format string, args ...any) {
 	if p.lastName == "" {
 		p.lastName = testName
 	} else if p.lastName != testName {
-		fmt.Fprintf(p.w, "=== CONT  %s\n", testName)
+		fmt.Fprintf(p.w, "%s=== NAME  %s\n", p.prefix(), testName)
 		p.lastName = testName
 	}
 
@@ -591,13 +643,10 @@ func CoverMode() string {
 // Verbose reports whether the -test.v flag is set.
 func Verbose() bool {
 	// Same as in Short.
-	if chatty == nil {
-		panic("testing: Verbose called before Init")
-	}
 	if !flag.Parsed() {
 		panic("testing: Verbose called before Parse")
 	}
-	return *chatty
+	return chatty.on
 }
 
 func (c *common) checkFuzzFn(name string) {
@@ -732,26 +781,33 @@ func (c *common) flushToParent(testName, format string, args ...any) {
 	defer c.mu.Unlock()
 
 	if len(c.output) > 0 {
+		// Add the current c.output to the print,
+		// and then arrange for the print to replace c.output.
+		// (This displays the logged output after the --- FAIL line.)
 		format += "%s"
 		args = append(args[:len(args):len(args)], c.output)
-		c.output = c.output[:0] // but why?
+		c.output = c.output[:0]
 	}
 
-	if c.chatty != nil && p.w == c.chatty.w {
+	if c.chatty != nil && (p.w == c.chatty.w || c.chatty.json) {
 		// We're flushing to the actual output, so track that this output is
 		// associated with a specific test (and, specifically, that the next output
 		// is *not* associated with that test).
 		//
 		// Moreover, if c.output is non-empty it is important that this write be
 		// atomic with respect to the output of other tests, so that we don't end up
-		// with confusing '=== CONT' lines in the middle of our '--- PASS' block.
+		// with confusing '=== NAME' lines in the middle of our '--- PASS' block.
 		// Neither humans nor cmd/test2json can parse those easily.
-		// (See https://golang.org/issue/40771.)
+		// (See https://go.dev/issue/40771.)
+		//
+		// If test2json is used, we never flush to parent tests,
+		// so that the json stream shows subtests as they finish.
+		// (See https://go.dev/issue/29811.)
 		c.chatty.Updatef(testName, format, args...)
 	} else {
 		// We're flushing to the output buffer of the parent test, which will
 		// itself follow a test-name header when it is finally flushed to stdout.
-		fmt.Fprintf(p.w, format, args...)
+		fmt.Fprintf(p.w, c.chatty.prefix()+format, args...)
 	}
 }
 
@@ -770,9 +826,14 @@ func (w indenter) Write(b []byte) (n int, err error) {
 		}
 		// An indent of 4 spaces will neatly align the dashes with the status
 		// indicator of the parent.
+		line := b[:end]
+		if line[0] == marker {
+			w.c.output = append(w.c.output, marker)
+			line = line[1:]
+		}
 		const indent = "    "
 		w.c.output = append(w.c.output, indent...)
-		w.c.output = append(w.c.output, b[:end]...)
+		w.c.output = append(w.c.output, line...)
 		b = b[end:]
 	}
 	return
@@ -1300,12 +1361,6 @@ func (t *T) Parallel() {
 	t.raceErrors += race.Errors()
 
 	if t.chatty != nil {
-		// Unfortunately, even though PAUSE indicates that the named test is *no
-		// longer* running, cmd/test2json interprets it as changing the active test
-		// for the purpose of log parsing. We could fix cmd/test2json, but that
-		// won't fix existing deployments of third-party tools that already shell
-		// out to older builds of cmd/test2json — so merely fixing cmd/test2json
-		// isn't enough for now.
 		t.chatty.Updatef(t.name, "=== PAUSE %s\n", t.name)
 	}
 
@@ -1551,6 +1606,9 @@ func (t *T) Run(name string, f func(t *T)) bool {
 		// parent tests by one of the subtests. Continue aborting up the chain.
 		runtime.Goexit()
 	}
+	if t.chatty != nil && t.chatty.json {
+		t.chatty.Updatef(t.parent.name, "=== NAME  %s\n", t.parent.name)
+	}
 	return !t.failed
 }
 
@@ -1713,6 +1771,7 @@ func MainStart(deps testDeps, tests []InternalTest, benchmarks []InternalBenchma
 }
 
 var testingTesting bool
+var realStderr *os.File
 
 // Run runs the tests. It returns an exit code to pass to os.Exit.
 func (m *M) Run() (code int) {
@@ -1723,7 +1782,7 @@ func (m *M) Run() (code int) {
 	// Count the number of calls to m.Run.
 	// We only ever expected 1, but we didn't enforce that,
 	// and now there are tests in the wild that call m.Run multiple times.
-	// Sigh. golang.org/issue/23129.
+	// Sigh. go.dev/issue/23129.
 	m.numRun++
 
 	// TestMain may have already called flag.Parse.
@@ -1731,6 +1790,44 @@ func (m *M) Run() (code int) {
 		flag.Parse()
 	}
 
+	if chatty.json {
+		// With -v=json, stdout and stderr are pointing to the same pipe,
+		// which is leading into test2json. In general, operating systems
+		// do a good job of ensuring that writes to the same pipe through
+		// different file descriptors are delivered whole, so that writing
+		// AAA to stdout and BBB to stderr simultaneously produces
+		// AAABBB or BBBAAA on the pipe, not something like AABBBA.
+		// However, the exception to this is when the pipe fills: in that
+		// case, Go's use of non-blocking I/O means that writing AAA
+		// or BBB might be split across multiple system calls, making it
+		// entirely possible to get output like AABBBA. The same problem
+		// happens inside the operating system kernel if we switch to
+		// blocking I/O on the pipe. This interleaved output can do things
+		// like print unrelated messages in the middle of a TestFoo line,
+		// which confuses test2json. Setting os.Stderr = os.Stdout will make
+		// them share a single pfd, which will hold a lock for each program
+		// write, preventing any interleaving.
+		//
+		// It might be nice to set Stderr = Stdout always, or perhaps if
+		// we can tell they are the same file, but for now -v=json is
+		// a very clear signal. Making the two files the same may cause
+		// surprises if programs close os.Stdout but expect to be able
+		// to continue to write to os.Stderr, but it's hard to see why a
+		// test would think it could take over global state that way.
+		//
+		// This fix only helps programs where the output is coming directly
+		// from Go code. It does not help programs in which a subprocess is
+		// writing to stderr or stdout at the same time that a Go test is writing output.
+		// It also does not help when the output is coming from the runtime,
+		// such as when using the print/println functions, since that code writes
+		// directly to fd 2 without any locking.
+		// We keep realStderr around to prevent fd 2 from being closed.
+		//
+		// See go.dev/issue/33419.
+		realStderr = os.Stderr
+		os.Stderr = os.Stdout
+	}
+
 	if *parallel < 1 {
 		fmt.Fprintln(os.Stderr, "testing: -parallel can only be given a positive integer")
 		flag.Usage()
@@ -1793,12 +1890,12 @@ func (m *M) Run() (code int) {
 				// with no obvious way to detect this problem (since no tests are running).
 				// So make 'no tests to run' a hard failure when testing package testing itself.
 				// The compile-only builders use -run=^$ to run no tests, so allow that.
-				fmt.Println("FAIL: package testing must run tests")
+				fmt.Print(chatty.prefix(), "FAIL: package testing must run tests\n")
 				testOk = false
 			}
 		}
 		if !testOk || !exampleOk || !fuzzTargetsOk || !runBenchmarks(m.deps.ImportPath(), m.deps.MatchString, m.benchmarks) || race.Errors() > 0 {
-			fmt.Println("FAIL")
+			fmt.Print(chatty.prefix(), "FAIL\n")
 			m.exitCode = 1
 			return
 		}
@@ -1806,7 +1903,7 @@ func (m *M) Run() (code int) {
 
 	fuzzingOk := runFuzzing(m.deps, m.fuzzTargets)
 	if !fuzzingOk {
-		fmt.Println("FAIL")
+		fmt.Print(chatty.prefix(), "FAIL\n")
 		if *isFuzzWorker {
 			m.exitCode = fuzzWorkerExitCode
 		} else {
@@ -1817,7 +1914,7 @@ func (m *M) Run() (code int) {
 
 	m.exitCode = 0
 	if !*isFuzzWorker {
-		fmt.Println("PASS")
+		fmt.Print(chatty.prefix(), "PASS\n")
 	}
 	return
 }