testing: report the failing test in a late log panic

Updates #29388

Change-Id: Icb0e6048d05fde7a5486b923ff62147edb5c8dac
Reviewed-on: https://go-review.googlesource.com/c/157617
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Reviewed-by: Damien Neil <dneil@google.com>

diff --git a/src/testing/sub_test.go b/src/testing/sub_test.go
index 8c989714a1c4369680838b28b3103c9990a3c726..5a6d51be592f99dfad5cae94fe445715b375597f 100644 (file)
--- a/src/testing/sub_test.go
+++ b/src/testing/sub_test.go
@@ -706,6 +706,55 @@ func TestRacyOutput(t *T) {
        }
 }
 
+// The late log message did not include the test name.  Issue 29388.
+func TestLogAfterComplete(t *T) {
+       ctx := newTestContext(1, newMatcher(regexp.MatchString, "", ""))
+       var buf bytes.Buffer
+       t1 := &T{
+               common: common{
+                       // Use a buffered channel so that tRunner can write
+                       // to it although nothing is reading from it.
+                       signal: make(chan bool, 1),
+                       w:      &buf,
+               },
+               context: ctx,
+       }
+
+       c1 := make(chan bool)
+       c2 := make(chan string)
+       tRunner(t1, func(t *T) {
+               t.Run("TestLateLog", func(t *T) {
+                       go func() {
+                               defer close(c2)
+                               defer func() {
+                                       p := recover()
+                                       if p == nil {
+                                               c2 <- "subtest did not panic"
+                                               return
+                                       }
+                                       s, ok := p.(string)
+                                       if !ok {
+                                               c2 <- fmt.Sprintf("subtest panic with unexpected value %v", p)
+                                               return
+                                       }
+                                       const want = "Log in goroutine after TestLateLog has completed"
+                                       if !strings.Contains(s, want) {
+                                               c2 <- fmt.Sprintf("subtest panic %q does not contain %q", s, want)
+                                       }
+                               }()
+
+                               <-c1
+                               t.Log("log after test")
+                       }()
+               })
+       })
+       close(c1)
+
+       if s := <-c2; s != "" {
+               t.Error(s)
+       }
+}
+
 func TestBenchmark(t *T) {
        res := Benchmark(func(b *B) {
                for i := 0; i < 5; i++ {

diff --git a/src/testing/testing.go b/src/testing/testing.go
index 0ac51b6fe5162521f5cf88e1346be71f923f1000..3068630e8a97685c686ca988913d58d9693ec308 100644 (file)
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -618,17 +618,20 @@ func (c *common) log(s string) {
 func (c *common) logDepth(s string, depth int) {
        c.mu.Lock()
        defer c.mu.Unlock()
-       // 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 {
+       if !c.done {
                c.output = append(c.output, c.decorate(s, depth+1)...)
+       } else {
+               // This test has already finished. Try and log this message
+               // with our parent. If we don't have a parent, panic.
+               for parent := c.parent; parent != nil; parent = parent.parent {
+                       parent.mu.Lock()
+                       defer parent.mu.Unlock()
+                       if !parent.done {
+                               parent.output = append(parent.output, parent.decorate(s, depth+1)...)
+                               return
+                       }
+               }
+               panic("Log in goroutine after " + c.name + " has completed")
        }
 }