testing: try to Log through parent if test has completed

If the test has already completed when a go routine with a panic
handler reports an error the location of the error call is lost.

Added logDepth to be able to log location of failure at different
depths down the stack.

Fixes #26720

Change-Id: I8b7789ddae757ef6f4bd315cb20356709f4fadec
Reviewed-on: https://go-review.googlesource.com/c/127596
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

diff --git a/src/testing/sub_test.go b/src/testing/sub_test.go
index 29803c06e2f9c2d3e3f4f8bf06535fa1492cafc8..e9b22335206e3822b08bf0c33d142a0c811f95a2 100644 (file)
--- a/src/testing/sub_test.go
+++ b/src/testing/sub_test.go
@@ -411,6 +411,29 @@ func TestTRun(t *T) {
                        ch <- true
                        <-ch
                },
+       }, {
+               desc: "log in finished sub test logs to parent",
+               ok:   false,
+               output: `
+               --- FAIL: log in finished sub test logs to parent (N.NNs)
+    sub_test.go:NNN: message2
+    sub_test.go:NNN: message1
+    sub_test.go:NNN: error`,
+               maxPar: 1,
+               f: func(t *T) {
+                       ch := make(chan bool)
+                       t.Run("sub", func(t2 *T) {
+                               go func() {
+                                       <-ch
+                                       t2.Log("message1")
+                                       ch <- true
+                               }()
+                       })
+                       t.Log("message2")
+                       ch <- true
+                       <-ch
+                       t.Errorf("error")
+               },
        }}
        for _, tc := range testCases {
                ctx := newTestContext(tc.maxPar, newMatcher(regexp.MatchString, "", ""))

diff --git a/src/testing/testing.go b/src/testing/testing.go
index 179987b699aafc1ee0939627a5625d0aae8f21a9..0bc222c0bb33873529b65979d3c1a0b4e7ed4813 100644 (file)
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -403,8 +403,8 @@ func (c *common) frameSkip(skip int) runtime.Frame {
 // decorate prefixes the string with the file and line of the call site
 // and inserts the final newline if needed and indentation spaces for formatting.
 // This function must be called with c.mu held.
-func (c *common) decorate(s string) string {
-       frame := c.frameSkip(3) // decorate + log + public function.
+func (c *common) decorate(s string, skip int) string {
+       frame := c.frameSkip(skip)
        file := frame.File
        line := frame.Line
        if file != "" {
@@ -599,9 +599,25 @@ func (c *common) FailNow() {
 
 // log generates the output. It's always at the same stack depth.
 func (c *common) log(s string) {
+       c.logDepth(s, 3) // logDepth + log + public function
+}
+
+// logDepth generates the output. At an arbitary stack depth
+func (c *common) logDepth(s string, depth int) {
        c.mu.Lock()
        defer c.mu.Unlock()
-       c.output = append(c.output, c.decorate(s)...)
+       // If this test has already finished try and log this message with our parent
+       // with this test name tagged so we know where it came from.
+       // If we don't have a parent panic.
+       if c.done {
+               if c.parent != nil {
+                       c.parent.logDepth(s, depth+1)
+               } else {
+                       panic("Log in goroutine after " + c.name + " has completed")
+               }
+       } else {
+               c.output = append(c.output, c.decorate(s, depth+1)...)
+       }
 }
 
 // Log formats its arguments using default formatting, analogous to Println,