runtime: call traceAdvance before exiting

This ensures the trace buffers are as up-to-date as possible right
before crashing. It increases the chance of finding the culprit for the
crash when looking at core dumps, e.g. if slowness is the cause for the
crash (monitor kills process).

Fixes #65319.

Change-Id: Iaf5551911b3b3b01ba65cb8749cf62a411e02d9c
Reviewed-on: https://go-review.googlesource.com/c/go/+/562616
Auto-Submit: Michael Knyszek <mknyszek@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Michael Knyszek <mknyszek@google.com>

diff --git a/src/runtime/crash_test.go b/src/runtime/crash_test.go
index 2eddbcaefcdefbe7a5cab5ef87a0dded75d9b649..9ba45b8f2a92229e3edb20f0e8ca360faf7312fe 100644 (file)
--- a/src/runtime/crash_test.go
+++ b/src/runtime/crash_test.go
@@ -6,16 +6,21 @@ package runtime_test
 
 import (
        "bytes"
+       "context"
        "errors"
        "flag"
        "fmt"
+       "internal/goexperiment"
        "internal/testenv"
+       tracev2 "internal/trace/v2"
+       "io"
        "log"
        "os"
        "os/exec"
        "path/filepath"
        "regexp"
        "runtime"
+       "runtime/trace"
        "strings"
        "sync"
        "testing"
@@ -874,6 +879,71 @@ func TestG0StackOverflow(t *testing.T) {
        runtime.G0StackOverflow()
 }
 
+// For TestCrashWhileTracing: test a panic without involving the testing
+// harness, as we rely on stdout only containing trace output.
+func init() {
+       if os.Getenv("TEST_CRASH_WHILE_TRACING") == "1" {
+               trace.Start(os.Stdout)
+               trace.Log(context.Background(), "xyzzy-cat", "xyzzy-msg")
+               panic("yzzyx")
+       }
+}
+
+func TestCrashWhileTracing(t *testing.T) {
+       if !goexperiment.ExecTracer2 {
+               t.Skip("skipping because this test is incompatible with the legacy tracer")
+       }
+
+       testenv.MustHaveExec(t)
+
+       cmd := testenv.CleanCmdEnv(testenv.Command(t, os.Args[0]))
+       cmd.Env = append(cmd.Env, "TEST_CRASH_WHILE_TRACING=1")
+       stdOut, err := cmd.StdoutPipe()
+       var errOut bytes.Buffer
+       cmd.Stderr = &errOut
+
+       if err := cmd.Start(); err != nil {
+               t.Fatalf("could not start subprocess: %v", err)
+       }
+       r, err := tracev2.NewReader(stdOut)
+       if err != nil {
+               t.Fatalf("could not create trace.NewReader: %v", err)
+       }
+       var seen bool
+       i := 1
+loop:
+       for ; ; i++ {
+               ev, err := r.ReadEvent()
+               if err != nil {
+                       if err != io.EOF {
+                               t.Errorf("error at event %d: %v", i, err)
+                       }
+                       break loop
+               }
+               switch ev.Kind() {
+               case tracev2.EventLog:
+                       v := ev.Log()
+                       if v.Category == "xyzzy-cat" && v.Message == "xyzzy-msg" {
+                               // Should we already stop reading here? More events may come, but
+                               // we're not guaranteeing a fully unbroken trace until the last
+                               // byte...
+                               seen = true
+                       }
+               }
+       }
+       if err := cmd.Wait(); err == nil {
+               t.Error("the process should have panicked")
+       }
+       if !seen {
+               t.Errorf("expected one matching log event matching, but none of the %d received trace events match", i)
+       }
+       t.Logf("stderr output:\n%s", errOut.String())
+       needle := "yzzyx\n"
+       if n := strings.Count(errOut.String(), needle); n != 1 {
+               t.Fatalf("did not find expected panic message %q\n(exit status %v)", needle, err)
+       }
+}
+
 // Test that panic message is not clobbered.
 // See issue 30150.
 func TestDoublePanic(t *testing.T) {

diff --git a/src/runtime/panic.go b/src/runtime/panic.go
index e6d1c5d9080b78e89de9d4756ced66fe5ca72650..99eb1c3e23a25420bc5beb1d69ab9175d1d28f23 100644 (file)
--- a/src/runtime/panic.go
+++ b/src/runtime/panic.go
@@ -759,6 +759,16 @@ func gopanic(e any) {
                fn()
        }
 
+       // If we're tracing, flush the current generation to make the trace more
+       // readable.
+       //
+       // TODO(aktau): Handle a panic from within traceAdvance more gracefully.
+       // Currently it would hang. Not handled now because it is very unlikely, and
+       // already unrecoverable.
+       if traceEnabled() {
+               traceAdvance(false)
+       }
+
        // ran out of deferred calls - old-school panic now
        // Because it is unsafe to call arbitrary user code after freezing
        // the world, we call preprintpanics to invoke all necessary Error

diff --git a/src/runtime/trace.go b/src/runtime/trace.go
index a9cfa22337e1bc29c86ef0c3a84e43fc4a070674..948a8da0cab560661747ef75ab516aa5b93f22ef 100644 (file)
--- a/src/runtime/trace.go
+++ b/src/runtime/trace.go
@@ -578,6 +578,9 @@ func StopTrace() {
        })
 }
 
+// traceAdvance is called from panic, it does nothing for the legacy tracer.
+func traceAdvance(stopTrace bool) {}
+
 // ReadTrace returns the next chunk of binary tracing data, blocking until data
 // is available. If tracing is turned off and all the data accumulated while it
 // was on has been returned, ReadTrace returns nil. The caller must copy the