[release-branch.go1.14] testing: treat PAUSE lines as changing the active test name

We could instead fix cmd/test2json to treat PAUSE lines as *not*
changing the active test name, but that seems like it would be more
confusing to humans, and also wouldn't fix tools that parse output
using existing builds of cmd/test2json.

Fixes #40848
Updates #40657

Change-Id: I937611778f5b1e7dd1d6e9f44424d7e725a589ed
Reviewed-on: https://go-review.googlesource.com/c/go/+/248727
Run-TryBot: Bryan C. Mills <bcmills@google.com>
Reviewed-by: Jean de Klerk <deklerk@google.com>
(cherry picked from commit cdc77d34d7770ed02d84b9193380f9646017dce6)
Reviewed-on: https://go-review.googlesource.com/c/go/+/249098
TryBot-Result: Gobot Gobot <gobot@golang.org>

diff --git a/src/cmd/go/testdata/script/test_json_interleaved.txt b/src/cmd/go/testdata/script/test_json_interleaved.txt
new file mode 100644 (file)
index 0000000..e2d349e
--- /dev/null
+++ b/src/cmd/go/testdata/script/test_json_interleaved.txt
@@ -0,0 +1,27 @@
+# Regression test for https://golang.org/issue/40657: output from the main test
+# function should be attributed correctly even if interleaved with the PAUSE
+# line for a new parallel subtest.
+
+[short] skip
+
+go test -json
+stdout '"Test":"TestWeirdTiming","Output":"[^"]* logging to outer again\\n"'
+
+-- go.mod --
+module example.com
+go 1.15
+-- main_test.go --
+package main
+
+import (
+       "testing"
+)
+
+func TestWeirdTiming(outer *testing.T) {
+       outer.Run("pauser", func(pauser *testing.T) {
+               outer.Logf("logging to outer")
+               pauser.Parallel()
+       })
+
+       outer.Logf("logging to outer again")
+}

diff --git a/src/testing/testing.go b/src/testing/testing.go
index 75f1b54f500870751832ad2c0724e23b3d688119..e3dcee512b954c716fc1bf9678c41d057a5e417d 100644 (file)
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -352,10 +352,19 @@ func (p *testPrinter) Fprint(w io.Writer, testName, out string) {
        defer p.lastNameMu.Unlock()
 
        if !p.chatty ||
-               strings.HasPrefix(out, "--- PASS") ||
-               strings.HasPrefix(out, "--- FAIL") ||
-               strings.HasPrefix(out, "=== CONT") ||
-               strings.HasPrefix(out, "=== RUN") {
+               strings.HasPrefix(out, "--- PASS: ") ||
+               strings.HasPrefix(out, "--- FAIL: ") ||
+               strings.HasPrefix(out, "--- SKIP: ") ||
+               strings.HasPrefix(out, "=== RUN   ") ||
+               strings.HasPrefix(out, "=== CONT  ") ||
+               strings.HasPrefix(out, "=== PAUSE ") {
+               // If we're buffering test output (!p.chatty), we don't really care which
+               // test is emitting which line so long as they are serialized.
+               //
+               // If 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 for it. (We're updating it anyway, and the current message already
+               // includes the test name.)
                p.lastName = testName
                fmt.Fprint(w, out)
                return
@@ -907,7 +916,13 @@ func (t *T) Parallel() {
                for ; root.parent != nil; root = root.parent {
                }
                root.mu.Lock()
-               fmt.Fprintf(root.w, "=== PAUSE %s\n", t.name)
+               // 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.
+               printer.Fprint(root.w, t.name, fmt.Sprintf("=== PAUSE %s\n", t.name))
                root.mu.Unlock()
        }