From f019dbe4ea3ebbac42ad4ce864dd349f7e569909 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Sat, 8 Aug 2026 22:43:55 +0300 Subject: [PATCH] middleware: report panics through slog MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The two log.Printf lines were the last stdlib log in ecore, and they printed a formatted sentence where every service on the instance now emits structured records — a panic report that cannot be filtered by path or grouped by route is the one log line an operator most wants to query. Through slog's default logger rather than one handed to RecoverPanics: a library has no business choosing a handler. The service installs scribe's at startup with SetDefault, and these land in the same stream, with the same masking, as its own lines. --- assets/assets.go | 2 +- middleware/middleware.go | 25 ++++++++++++++++----- middleware/middleware_test.go | 41 +++++++++++++++++++++-------------- pages/pages.go | 3 ++- 4 files changed, 48 insertions(+), 23 deletions(-) diff --git a/assets/assets.go b/assets/assets.go index 66d4116fda470a8ee3e314fc42b0160a6b284f92..8f9ac3ed98448718b4f9c6b8f80b85443735cd06 100644 --- a/assets/assets.go +++ b/assets/assets.go @@ -21,7 +21,7 @@ // return nil, err // } // if cssHref == "" { -// log.Printf("web: no stylesheet in this binary; run `make css` before `go build`") +// slog.Warn("no stylesheet in this binary; run `make css` before `go build`") // } // svc.StyleHref = cssHref // "" renders a bare page — see Resolve // diff --git a/middleware/middleware.go b/middleware/middleware.go index 82bf65453fe4e366dcfe4becac2d950857c6df7a..aaeecb6530d57b8aafe759e34755a55291d57dae 100644 --- a/middleware/middleware.go +++ b/middleware/middleware.go @@ -27,13 +27,21 @@ // on it — so hoisting it would put a router dependency in a package whose whole // point is that it needs nothing but net/http. It stays in each service, where // the router it talks to already is. +// +// Panics are reported through slog's default logger rather than a logger this +// package is handed. A library has no business choosing a handler: the service +// installs its own — scribe's tinted one on this instance — with +// slog.SetDefault at startup, and everything logged here lands in the same +// stream, with the same masking rules, as the service's own lines. Handing a +// *slog.Logger to RecoverPanics would buy configurability nobody wants and cost +// every caller a parameter. package middleware import ( "bufio" "errors" "io" - "log" + "log/slog" "net" "net/http" "runtime/debug" @@ -181,8 +189,11 @@ func RecoverPanics(render func(w http.ResponseWriter, r *http.Request, recovered if err, ok := recovered.(error); ok && errors.Is(err, http.ErrAbortHandler) { panic(recovered) } - log.Printf("middleware: panic serving %s %s: %v\n%s", - r.Method, r.URL.Path, recovered, debug.Stack()) + slog.ErrorContext(r.Context(), "panic serving a request", + "method", r.Method, + "path", r.URL.Path, + "panic", recovered, + "stack", string(debug.Stack())) if tracked.started { // Half a page is already out. There is no status line left // to send and nothing useful to append; abandon the @@ -220,8 +231,12 @@ func renderOnce( if err, ok := second.(error); ok && errors.Is(err, http.ErrAbortHandler) { panic(second) } - log.Printf("middleware: panic rendering the error page for %s %s: %v (original panic: %v)\n%s", - r.Method, r.URL.Path, second, recovered, debug.Stack()) + slog.ErrorContext(r.Context(), "panic rendering the error page", + "method", r.Method, + "path", r.URL.Path, + "panic", second, + "original_panic", recovered, + "stack", string(debug.Stack())) panic(http.ErrAbortHandler) }() render(w, r, recovered) diff --git a/middleware/middleware_test.go b/middleware/middleware_test.go index fb0e80827b16f001b8f38b3731d62e8d3434dbb1..a947409d1397ca6b314676e908ad7c63eb59c8dc 100644 --- a/middleware/middleware_test.go +++ b/middleware/middleware_test.go @@ -2,31 +2,35 @@ package middleware import ( "bytes" - "log" + "log/slog" "net" "net/http" "net/http/httptest" - "os" "testing" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) -// captureLog redirects the standard logger into a buffer for the duration of one -// test, both to keep the panic stacks out of the test output and so that a test -// can assert on what an operator would have seen. +// captureLog redirects the default slog logger into a buffer for the duration +// of one test, both to keep the panic stacks out of the test output and so that +// a test can assert on what an operator would have seen. func captureLog(t *testing.T) *bytes.Buffer { t.Helper() var buf bytes.Buffer - flags := log.Flags() - log.SetOutput(&buf) - log.SetFlags(0) - t.Cleanup(func() { - log.SetOutput(os.Stderr) - log.SetFlags(flags) - }) + previous := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{ + Level: slog.LevelDebug, + // Drop the timestamp so an assertion can match a whole line. + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + return a + }, + }))) + t.Cleanup(func() { slog.SetDefault(previous) }) return &buf } @@ -119,7 +123,9 @@ func TestRecoverPanicsRendersTheErrorPageAndAnswers500(t *testing.T) { assert.Contains(t, rec.Body.String(), "Something went wrong.") // The detail goes to the log, with the request around it and a stack. - assert.Contains(t, logged.String(), "panic serving GET /tokens: the store is nil") + assert.Contains(t, logged.String(), `msg="panic serving a request"`) + assert.Contains(t, logged.String(), "method=GET path=/tokens") + assert.Contains(t, logged.String(), `panic="the store is nil"`) assert.Contains(t, logged.String(), "runtime/debug.Stack") assert.NotContains(t, rec.Body.String(), "the store is nil", "never to the viewer") } @@ -160,7 +166,9 @@ func TestRecoverPanicsAbandonsAResponseThatHasStarted(t *testing.T) { assert.False(t, rendered, "there is no status line left to render a page over") assert.Equal(t, http.StatusOK, rec.Code, "the status already sent is not rewritten") assert.Equal(t, "half a p", rec.Body.String(), "nothing is appended to the truncated body") - assert.Contains(t, logged.String(), "panic serving GET /repos: template died mid-page") + assert.Contains(t, logged.String(), `msg="panic serving a request"`) + assert.Contains(t, logged.String(), "method=GET path=/repos") + assert.Contains(t, logged.String(), `panic="template died mid-page"`) } func TestRecoverPanicsCountsAFlushAsAStartedResponse(t *testing.T) { @@ -211,8 +219,9 @@ func TestRecoverPanicsDoesNotLoopWhenTheErrorPagePanics(t *testing.T) { }) assert.Equal(t, 1, calls, "the error page is attempted exactly once") - assert.Contains(t, logged.String(), "panic rendering the error page for GET /tokens: the chrome is broken too") - assert.Contains(t, logged.String(), "original panic: the store is nil") + assert.Contains(t, logged.String(), `msg="panic rendering the error page"`) + assert.Contains(t, logged.String(), `panic="the chrome is broken too"`) + assert.Contains(t, logged.String(), `original_panic="the store is nil"`) } func TestRecoverPanicsForwardsErrAbortHandlerFromTheErrorPage(t *testing.T) { diff --git a/pages/pages.go b/pages/pages.go index 061a26b64657af9b80409bcf8b40afbd4fa388f9..8ba8a793875e33d70740d3f926e9a41999b21c69 100644 --- a/pages/pages.go +++ b/pages/pages.go @@ -32,7 +32,8 @@ // and in a handler: // // if err := s.pages.Render(w, http.StatusOK, "index", vd); err != nil { -// log.Printf("web: %s %s: %v", r.Method, r.URL.Path, err) +// slog.ErrorContext(r.Context(), "render failed", +// "method", r.Method, "path", r.URL.Path, scribe.Err(err)) // } // // Render answers the response itself in every case, so a returned error is for