log/slog: catch panics in LogValue

If a LogValue call panics, recover and return an error instead.

The error contains some stack information to make it easier to
find the problem. A number of people complained that panics
in fmt.Formatter.Format functions are hard to debug because
there is no context.

This is an example of the error text:

    LogValue panicked
    called from log/slog.panickingLogValue.LogValue (/usr/local/google/home/jba/repos/go/src/log/slog/value_test.go:221)
    called from log/slog.Value.resolve (/usr/local/google/home/jba/repos/go/src/log/slog/value.go:465)
    called from log/slog.Value.Resolve (/usr/local/google/home/jba/repos/go/src/log/slog/value.go:446)
    called from log/slog.TestLogValue (/usr/local/google/home/jba/repos/go/src/log/slog/value_test.go:192)
    called from testing.tRunner (/usr/local/google/home/jba/repos/go/src/testing/testing.go:1595)
    (rest of stack elided)

Fixes #59141.

Change-Id: I62e6ff6968d1aa34873e955c2d606d25418a673b
Reviewed-on: https://go-review.googlesource.com/c/go/+/484097
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Alan Donovan <adonovan@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>

diff --git a/src/log/slog/value.go b/src/log/slog/value.go
index fcfc884dc3abde81997736ad94b2b7ae9d91faa7..d07d9e33a40b7fa39311a42da91223f1387e3f88 100644 (file)
--- a/src/log/slog/value.go
+++ b/src/log/slog/value.go
@@ -7,8 +7,10 @@ package slog
 import (
        "fmt"
        "math"
+       "runtime"
        "slices"
        "strconv"
+       "strings"
        "time"
        "unsafe"
 )
@@ -448,8 +450,14 @@ func (v Value) Resolve() Value {
        return v
 }
 
-func (v Value) resolve() Value {
+func (v Value) resolve() (rv Value) {
        orig := v
+       defer func() {
+               if r := recover(); r != nil {
+                       rv = AnyValue(fmt.Errorf("LogValue panicked\n%s", stack(3, 5)))
+               }
+       }()
+
        for i := 0; i < maxLogValues; i++ {
                if v.Kind() != KindLogValuer {
                        return v
@@ -460,6 +468,30 @@ func (v Value) resolve() Value {
        return AnyValue(err)
 }
 
+func stack(skip, nFrames int) string {
+       pcs := make([]uintptr, nFrames+1)
+       n := runtime.Callers(skip+1, pcs)
+       if n == 0 {
+               return "(no stack)"
+       }
+       frames := runtime.CallersFrames(pcs[:n])
+       var b strings.Builder
+       i := 0
+       for {
+               frame, more := frames.Next()
+               fmt.Fprintf(&b, "called from %s (%s:%d)\n", frame.Function, frame.File, frame.Line)
+               if !more {
+                       break
+               }
+               i++
+               if i >= nFrames {
+                       fmt.Fprintf(&b, "(rest of stack elided)\n")
+                       break
+               }
+       }
+       return b.String()
+}
+
 // resolveAttrs replaces the values of the given Attrs with their
 // resolutions.
 func resolveAttrs(as []Attr) {

diff --git a/src/log/slog/value_test.go b/src/log/slog/value_test.go
index d2c427b96ef5501b664125dcdf32b554244fa336..e0c60c36527b87293e75df2f42802e636b67c44d 100644 (file)
--- a/src/log/slog/value_test.go
+++ b/src/log/slog/value_test.go
@@ -7,6 +7,7 @@ package slog
 import (
        "fmt"
        "reflect"
+       "strings"
        "testing"
        "time"
        "unsafe"
@@ -185,6 +186,20 @@ func TestLogValue(t *testing.T) {
        if !attrsEqual(got2, want2) {
                t.Errorf("got %v, want %v", got2, want2)
        }
+
+       // Verify that panics in Resolve are caught and turn into errors.
+       v = AnyValue(panickingLogValue{})
+       got = v.Resolve().Any()
+       gotErr, ok := got.(error)
+       if !ok {
+               t.Errorf("expected error, got %T", got)
+       }
+       // The error should provide some context information.
+       // We'll just check that this function name appears in it.
+       fmt.Println(got)
+       if got, want := gotErr.Error(), "TestLogValue"; !strings.Contains(got, want) {
+               t.Errorf("got %q, want substring %q", got, want)
+       }
 }
 
 func TestZeroTime(t *testing.T) {
@@ -201,6 +216,10 @@ type replace struct {
 
 func (r *replace) LogValue() Value { return r.v }
 
+type panickingLogValue struct{}
+
+func (panickingLogValue) LogValue() Value { panic("bad") }
+
 // A Value with "unsafe" strings is significantly faster:
 // safe:  1785 ns/op, 0 allocs
 // unsafe: 690 ns/op, 0 allocs