feat: add gqlgen Recover that logs panics as one structured record (#206)
otelsetup / test (push) Successful in 43s
otelsetup / vulnerabilities (push) Successful in 44s
Unbound Release / Check Preconditions (push) Successful in 1s
Unbound Release / Create Tag (push) Skipped
Unbound Release / Create Release (push) Successful in 4s
Unbound Release / Generate Changelog and Handle PR (push) Successful in 9s
Release / release (push) Successful in 14s
pre-commit / pre-commit (push) Successful in 2m25s
otelsetup / test (push) Successful in 43s
otelsetup / vulnerabilities (push) Successful in 44s
Unbound Release / Check Preconditions (push) Successful in 1s
Unbound Release / Create Tag (push) Skipped
Unbound Release / Create Release (push) Successful in 4s
Unbound Release / Generate Changelog and Handle PR (push) Successful in 9s
Release / release (push) Successful in 14s
pre-commit / pre-commit (push) Successful in 2m25s
## 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: #206
This commit was merged in pull request #206.
This commit is contained in:
1 parent
9fe1a21c02
commit
17130005c9
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