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>

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, "", ""))

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 {
+func (c *common) decorate(s string, skip int) string {
-	frame := c.frameSkip(3) // decorate + log + public function.
+	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,