From 17130005c9205bd477d74f59fb33e06c2b1325c3 Mon Sep 17 00:00:00 2001 From: Joakim Olsson Date: Fri, 16 Oct 2026 23:12:44 +0000 Subject: [PATCH] feat: add gqlgen Recover that logs panics as one structured record (#206) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary gqlgen's `graphql.DefaultRecover` prints a recovered resolver panic and `debug.PrintStack()` to stderr, so the log collector stores every stack line as a separate, level-less entry (~60 entries per panic in production). Adds `otelsetup.Recover` (`func(ctx context.Context, err any) error`, a `graphql.RecoverFunc` for gqlgen v0.17.95): - logs the panic as **one** ERROR record via `slog.Default().ErrorContext` (the default logger services set up through `logging.SetupLogger`), with `panic`, `stack` (`debug.Stack()`) and `path` (GraphQL field path, when available) attributes - records the error on the active span (`RecordError` with stack trace, `SetStatus(codes.Error)`) - returns the generic `internal system error` gqlerror to the client, without the panic text Services install it with `srv.SetRecoverFunc(otelsetup.Recover)`. ## Test plan - `TestRecover`: error and non-error panic values; asserts the generic gqlerror, no panic text leak, exactly one ERROR log record with panic/stack attributes, and span status Error with an `exception` event carrying message and stacktrace (in-memory `tracetest.SpanRecorder`) - `go test -race ./...` passes, `prek run --all-files` passes 🤖 Generated with [Claude Code](https://claude.com/claude-code) https://claude.ai/code/session_01H6eVuR4Yt3m7TbDTDwyZJi Reviewed-on: https://git.unbound.se/shiny/otelsetup/pulls/206 --- CLAUDE.md | 8 ++++ go.mod | 2 +- recover.go | 41 +++++++++++++++++ recover_test.go | 117 ++++++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 167 insertions(+), 1 deletion(-) create mode 100644 recover.go create mode 100644 recover_test.go diff --git a/CLAUDE.md b/CLAUDE.md index e8527c4..f971fe8 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -28,6 +28,12 @@ defer shutdown(ctx) // Wrap HTTP handlers with tracing 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 @@ -37,6 +43,8 @@ http.Handle("/", otelsetup.Handler(myHandler)) - **Logging** - Stdout log exporter - **Propagation** - TraceContext and Baggage propagation - **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 diff --git a/go.mod b/go.mod index c4afe81..1405d6a 100644 --- a/go.mod +++ b/go.mod @@ -6,6 +6,7 @@ require ( codeberg.org/eventsourced/eventsourced v1.24.0 codeberg.org/eventsourced/pg/v2 v2.3.0 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/exporters/otlp/otlpmetric/otlpmetrichttp 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/sethvargo/go-retry v0.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/otel/exporters/otlp/otlptrace v1.47.0 // indirect go.opentelemetry.io/otel/log v1.47.0 // indirect diff --git a/recover.go b/recover.go new file mode 100644 index 0000000..f6c0aaf --- /dev/null +++ b/recover.go @@ -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") +} diff --git a/recover_test.go b/recover_test.go new file mode 100644 index 0000000..12db295 --- /dev/null +++ b/recover_test.go @@ -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") + } + }) + } +}