feat: add gqlgen Recover that logs panics as one structured record
gqlgen's DefaultRecover prints the panic and debug.PrintStack() to stderr, so the log collector stores every stack line as a separate, level-less entry. Recover logs the panic as a single ERROR record via slog.Default() with panic, stack and path attributes, records it on the active span with status Error, and returns the generic "internal system error" without leaking the panic text. Install with srv.SetRecoverFunc(otelsetup.Recover). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01H6eVuR4Yt3m7TbDTDwyZJi
This commit is contained in:
1 parent
9fe1a21c02
commit
ff0585ad68
4 files changed
+167
-1
No files matched your search
@@ -28,6 +28,12 @@ defer shutdown(ctx)
|
|||||||
|
|
||||||
// Wrap HTTP handlers with tracing
|
// Wrap HTTP handlers with tracing
|
||||||
http.Handle("/", otelsetup.Handler(myHandler))
|
http.Handle("/", otelsetup.Handler(myHandler))
|
||||||
|
|
||||||
|
// gqlgen server hooks
|
||||||
|
srv.AroundOperations(otelsetup.AroundOperations)
|
||||||
|
srv.AroundRootFields(otelsetup.AroundRootFields)
|
||||||
|
srv.AroundFields(otelsetup.AroundFields)
|
||||||
|
srv.SetRecoverFunc(otelsetup.Recover)
|
||||||
```
|
```
|
||||||
|
|
||||||
### Features
|
### Features
|
||||||
@@ -37,6 +43,8 @@ http.Handle("/", otelsetup.Handler(myHandler))
|
|||||||
- **Logging** - Stdout log exporter
|
- **Logging** - Stdout log exporter
|
||||||
- **Propagation** - TraceContext and Baggage propagation
|
- **Propagation** - TraceContext and Baggage propagation
|
||||||
- **HTTP Handler** - Middleware for automatic span creation
|
- **HTTP Handler** - Middleware for automatic span creation
|
||||||
|
- **gqlgen hooks** - Spans per operation, root field and resolver field
|
||||||
|
- **gqlgen recover** - `Recover` logs a resolver panic as one ERROR record via `slog.Default()` (attributes `panic`, `stack`, `path`), records it on the active span with status Error, and returns the generic "internal system error" to the client (gqlgen's default prints the stack to stderr line by line)
|
||||||
|
|
||||||
### Environment Variables
|
### Environment Variables
|
||||||
|
|
||||||
|
|||||||
@@ -6,6 +6,7 @@ require (
|
|||||||
codeberg.org/eventsourced/eventsourced v1.24.0
|
codeberg.org/eventsourced/eventsourced v1.24.0
|
||||||
codeberg.org/eventsourced/pg/v2 v2.3.0
|
codeberg.org/eventsourced/pg/v2 v2.3.0
|
||||||
github.com/99designs/gqlgen v0.17.95
|
github.com/99designs/gqlgen v0.17.95
|
||||||
|
github.com/vektah/gqlparser/v2 v2.5.37
|
||||||
go.opentelemetry.io/otel v1.47.0
|
go.opentelemetry.io/otel v1.47.0
|
||||||
go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0
|
go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0
|
||||||
go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0
|
go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0
|
||||||
@@ -30,7 +31,6 @@ require (
|
|||||||
github.com/pressly/goose/v3 v3.28.0 // indirect
|
github.com/pressly/goose/v3 v3.28.0 // indirect
|
||||||
github.com/sethvargo/go-retry v0.4.0 // indirect
|
github.com/sethvargo/go-retry v0.4.0 // indirect
|
||||||
github.com/sosodev/duration v1.4.0 // indirect
|
github.com/sosodev/duration v1.4.0 // indirect
|
||||||
github.com/vektah/gqlparser/v2 v2.5.37 // indirect
|
|
||||||
go.opentelemetry.io/auto/sdk v1.2.1 // indirect
|
go.opentelemetry.io/auto/sdk v1.2.1 // indirect
|
||||||
go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 // indirect
|
go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 // indirect
|
||||||
go.opentelemetry.io/otel/log v1.47.0 // indirect
|
go.opentelemetry.io/otel/log v1.47.0 // indirect
|
||||||
|
|||||||
+41
@@ -0,0 +1,41 @@
|
|||||||
|
package otelsetup
|
||||||
|
|
||||||
|
import (
|
||||||
|
"context"
|
||||||
|
"fmt"
|
||||||
|
"log/slog"
|
||||||
|
"runtime/debug"
|
||||||
|
|
||||||
|
"github.com/99designs/gqlgen/graphql"
|
||||||
|
"github.com/vektah/gqlparser/v2/gqlerror"
|
||||||
|
"go.opentelemetry.io/otel/codes"
|
||||||
|
"go.opentelemetry.io/otel/trace"
|
||||||
|
)
|
||||||
|
|
||||||
|
// Recover is a gqlgen recover function, installed with srv.SetRecoverFunc(otelsetup.Recover).
|
||||||
|
// Unlike graphql.DefaultRecover, which prints the stack to stderr line by line, it logs the
|
||||||
|
// panic as a single structured ERROR record (via slog.Default) with the stack as an attribute,
|
||||||
|
// records it on the active span and marks the span as failed. The client gets the same generic
|
||||||
|
// "internal system error" as with the default, without the panic text.
|
||||||
|
func Recover(ctx context.Context, err any) error {
|
||||||
|
stack := string(debug.Stack())
|
||||||
|
panicErr, ok := err.(error)
|
||||||
|
if !ok {
|
||||||
|
panicErr = fmt.Errorf("%v", err)
|
||||||
|
}
|
||||||
|
|
||||||
|
attrs := []any{
|
||||||
|
slog.String("panic", panicErr.Error()),
|
||||||
|
slog.String("stack", stack),
|
||||||
|
}
|
||||||
|
if fc := graphql.GetFieldContext(ctx); fc != nil {
|
||||||
|
attrs = append(attrs, slog.String("path", fc.Path().String()))
|
||||||
|
}
|
||||||
|
slog.Default().ErrorContext(ctx, "recovered panic in graphql resolver", attrs...)
|
||||||
|
|
||||||
|
span := trace.SpanFromContext(ctx)
|
||||||
|
span.RecordError(panicErr, trace.WithStackTrace(true))
|
||||||
|
span.SetStatus(codes.Error, "panic: "+panicErr.Error())
|
||||||
|
|
||||||
|
return gqlerror.Errorf("internal system error")
|
||||||
|
}
|
||||||
+117
@@ -0,0 +1,117 @@
|
|||||||
|
package otelsetup
|
||||||
|
|
||||||
|
import (
|
||||||
|
"context"
|
||||||
|
"errors"
|
||||||
|
"log/slog"
|
||||||
|
"strings"
|
||||||
|
"sync"
|
||||||
|
"testing"
|
||||||
|
|
||||||
|
"github.com/99designs/gqlgen/graphql"
|
||||||
|
"github.com/vektah/gqlparser/v2/gqlerror"
|
||||||
|
"go.opentelemetry.io/otel/codes"
|
||||||
|
sdktrace "go.opentelemetry.io/otel/sdk/trace"
|
||||||
|
"go.opentelemetry.io/otel/sdk/trace/tracetest"
|
||||||
|
)
|
||||||
|
|
||||||
|
type recordingHandler struct {
|
||||||
|
mu sync.Mutex
|
||||||
|
records []slog.Record
|
||||||
|
}
|
||||||
|
|
||||||
|
func (h *recordingHandler) Enabled(context.Context, slog.Level) bool { return true }
|
||||||
|
|
||||||
|
func (h *recordingHandler) Handle(_ context.Context, r slog.Record) error {
|
||||||
|
h.mu.Lock()
|
||||||
|
defer h.mu.Unlock()
|
||||||
|
h.records = append(h.records, r.Clone())
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
|
||||||
|
func (h *recordingHandler) WithAttrs([]slog.Attr) slog.Handler { return h }
|
||||||
|
func (h *recordingHandler) WithGroup(string) slog.Handler { return h }
|
||||||
|
|
||||||
|
func TestRecover(t *testing.T) {
|
||||||
|
var _ graphql.RecoverFunc = Recover
|
||||||
|
|
||||||
|
tests := []struct {
|
||||||
|
name string
|
||||||
|
panicVal any
|
||||||
|
wantPanic string
|
||||||
|
}{
|
||||||
|
{name: "error value", panicVal: errors.New("runtime error: invalid memory address or nil pointer dereference"), wantPanic: "runtime error: invalid memory address or nil pointer dereference"},
|
||||||
|
{name: "string value", panicVal: "boom", wantPanic: "boom"},
|
||||||
|
}
|
||||||
|
for _, tt := range tests {
|
||||||
|
t.Run(tt.name, func(t *testing.T) {
|
||||||
|
h := &recordingHandler{}
|
||||||
|
prev := slog.Default()
|
||||||
|
slog.SetDefault(slog.New(h))
|
||||||
|
t.Cleanup(func() { slog.SetDefault(prev) })
|
||||||
|
|
||||||
|
sr := tracetest.NewSpanRecorder()
|
||||||
|
tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sr))
|
||||||
|
ctx, span := tp.Tracer("test").Start(context.Background(), "resolver")
|
||||||
|
|
||||||
|
err := Recover(ctx, tt.panicVal)
|
||||||
|
span.End()
|
||||||
|
|
||||||
|
var gqlErr *gqlerror.Error
|
||||||
|
if !errors.As(err, &gqlErr) || gqlErr.Message != "internal system error" {
|
||||||
|
t.Fatalf("Recover() error = %v, want gqlerror \"internal system error\"", err)
|
||||||
|
}
|
||||||
|
if strings.Contains(err.Error(), tt.wantPanic) {
|
||||||
|
t.Errorf("Recover() error leaks panic text: %v", err)
|
||||||
|
}
|
||||||
|
|
||||||
|
if len(h.records) != 1 {
|
||||||
|
t.Fatalf("got %d log records, want exactly 1", len(h.records))
|
||||||
|
}
|
||||||
|
rec := h.records[0]
|
||||||
|
if rec.Level != slog.LevelError {
|
||||||
|
t.Errorf("log level = %v, want ERROR", rec.Level)
|
||||||
|
}
|
||||||
|
got := map[string]string{}
|
||||||
|
rec.Attrs(func(a slog.Attr) bool {
|
||||||
|
got[a.Key] = a.Value.String()
|
||||||
|
return true
|
||||||
|
})
|
||||||
|
if got["panic"] != tt.wantPanic {
|
||||||
|
t.Errorf("panic attr = %q, want %q", got["panic"], tt.wantPanic)
|
||||||
|
}
|
||||||
|
if !strings.Contains(got["stack"], "goroutine") {
|
||||||
|
t.Errorf("stack attr missing stack trace: %q", got["stack"])
|
||||||
|
}
|
||||||
|
|
||||||
|
spans := sr.Ended()
|
||||||
|
if len(spans) != 1 {
|
||||||
|
t.Fatalf("got %d spans, want 1", len(spans))
|
||||||
|
}
|
||||||
|
s := spans[0]
|
||||||
|
if s.Status().Code != codes.Error {
|
||||||
|
t.Errorf("span status = %v, want Error", s.Status().Code)
|
||||||
|
}
|
||||||
|
var exception bool
|
||||||
|
for _, ev := range s.Events() {
|
||||||
|
if ev.Name != "exception" {
|
||||||
|
continue
|
||||||
|
}
|
||||||
|
exception = true
|
||||||
|
attrs := map[string]string{}
|
||||||
|
for _, kv := range ev.Attributes {
|
||||||
|
attrs[string(kv.Key)] = kv.Value.String()
|
||||||
|
}
|
||||||
|
if attrs["exception.message"] != tt.wantPanic {
|
||||||
|
t.Errorf("exception.message = %q, want %q", attrs["exception.message"], tt.wantPanic)
|
||||||
|
}
|
||||||
|
if attrs["exception.stacktrace"] == "" {
|
||||||
|
t.Error("exception event has no stacktrace")
|
||||||
|
}
|
||||||
|
}
|
||||||
|
if !exception {
|
||||||
|
t.Error("span has no exception event")
|
||||||
|
}
|
||||||
|
})
|
||||||
|
}
|
||||||
|
}
|
||||||
Reference in new issue
Block a user