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 <[email protected]>
LUCI-TryBot-Result: Go LUCI <[email protected]>
Reviewed-by: Michael Knyszek <[email protected]>

Author: aktau

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) {

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

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