fix(api): log the panic value and stack behind the opaque 500

withRecover turned a panicking handler into a 500 envelope and threw the panic
away. The client is meant to get an opaque "internal error" — that part is
right — but nothing was written server-side, so a recovered panic was an
untraceable 500: an operator holding "internal error" has no message, no
stack and no request to grep for, and diagnosis degrades into guessing against
a live install. That is what it cost during the email-OTP report.

The panic value, a stack and the method+path are now logged first, keyed by
the same request_id writeError already stamps on unmapped errors, so the
client envelope and the server log can be joined. The test pins all three
markers plus the unchanged 500/"panic" response, because a silent recover
looks exactly like a working one from the outside.
This commit is contained in:
flyemoji committed 2026-07-22 14:40:42 +09:00
1 parent c4c964578e
commit a8c4077202
2 files changed
+42

No files matched your search

+32
View File
@@ -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.
+10
View File
@@ -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"))
}
}()