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>
This commit is contained in:
Jonathan Amsterdam 2023-04-12 10:07:35 -04:00
parent f3e6f0f296
commit 38531c6290
2 changed files with 52 additions and 1 deletions

View File

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

View File

@ -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