diff --git a/internal/api/handlers_email_otp_test.go b/internal/api/handlers_email_otp_test.go index 0715719..891da6f 100644 --- a/internal/api/handlers_email_otp_test.go +++ b/internal/api/handlers_email_otp_test.go @@ -1,8 +1,10 @@ package api import ( + "bytes" "context" "errors" + "log" "net/http" "net/http/httptest" "strings" @@ -107,6 +109,36 @@ func TestEmailOTPVertical(t *testing.T) { } } +// TestWithRecoverLogsPanicStack pins the observability contract: a recovered panic +// must still leave the client an opaque 500 "panic", but the panic value, a stack, +// and the request path MUST be logged first — otherwise a 500 like the email-OTP +// report is untraceable (an operator has nothing to grep for). Regression guard for +// the silent recover that cost a live debugging session. +func TestWithRecoverLogsPanicStack(t *testing.T) { + var buf bytes.Buffer + old := log.Writer() + log.SetOutput(&buf) + defer log.SetOutput(old) + + h := withRequestID(withRecover(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + panic("boom-xyz") + }))) + w := httptest.NewRecorder() + h.ServeHTTP(w, httptest.NewRequest("POST", "/api/v1/account/email/start", nil)) + + if w.Code != http.StatusInternalServerError || errCode(w.Body.Bytes()) != "panic" { + t.Fatalf("recovered response = %d %q, want 500 panic (%s)", w.Code, errCode(w.Body.Bytes()), w.Body.String()) + } + logged := buf.String() + // The panic value, a real stack (debug.Stack always opens with "goroutine"), and + // the path — the three things a grep needs to find and place the fault. + for _, want := range []string{"boom-xyz", "goroutine", "/api/v1/account/email/start"} { + if !strings.Contains(logged, want) { + t.Fatalf("panic log missing %q; got:\n%s", want, logged) + } + } +} + // TestEmailOTPStartValidation covers the mint-side input gate and the no-mailer // fallback (the demo path): a malformed address never mints, and a nil Mailer still // persists a code (logged server-side) so the verify flow stays exercisable. diff --git a/internal/api/middleware.go b/internal/api/middleware.go index b25ab30..66ba387 100644 --- a/internal/api/middleware.go +++ b/internal/api/middleware.go @@ -4,7 +4,9 @@ import ( "context" "crypto/rand" "encoding/hex" + "log" "net/http" + "runtime/debug" ) // withRequestID assigns a request id (honoring a WELL-FORMED inbound X-Request-Id) @@ -57,10 +59,18 @@ func validRequestID(id string) bool { // withRecover turns a panicking handler into a 500 envelope instead of a // dropped connection. +// +// The client gets an opaque "internal error", but the panic value and stack are +// logged FIRST, keyed by the same request_id — the same contract writeError keeps +// for unmapped errors (see errors.go). Without it a recovered panic is an +// untraceable 500: an operator holding "internal error" has nothing to grep for, +// and diagnosis degrades into guessing against a live install. func withRecover(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { defer func() { if rec := recover(); rec != nil { + log.Printf("api: %s %s: panic (request_id=%s): %v\n%s", + r.Method, r.URL.Path, requestIDFromContext(r.Context()), rec, debug.Stack()) writeError(w, r, newError(http.StatusInternalServerError, "panic", "internal error")) } }()