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
 }