From c30145ed2556c23fe7c863a0287297ad1656bdb6 Mon Sep 17 00:00:00 2001 From: Jakub Zych Date: Mon, 12 Oct 2026 11:19:12 +0200 Subject: [PATCH] fix(14.2): WR-02 499 only for a 5xx caused by the client going away Every 5xx became 499 once the request context was cancelled, so a panic or a real database error on a request the browser had abandoned passed the phase gate's 5xx scan. Now a 5xx is logged as 499 only when the client had already gone when the status was written and the handler did not panic; recoverJSON and recoverBare mark the access log entry. Every record of an abandoned request carries client_gone=true. The gate self-test plants a 5xx with client_gone=true and must refuse it. --- docs/services/logging.md | 3 +- modules/surf/README.md | 2 +- modules/surf/accesslog.go | 72 +++++++++++++++++++++++--------- modules/surf/accesslog_test.go | 76 +++++++++++++++++++++++++++------- modules/surf/router.go | 2 + scripts/check-phase14.2.sh | 7 +++- 6 files changed, 123 insertions(+), 39 deletions(-) diff --git a/docs/services/logging.md b/docs/services/logging.md index 456497f..35f5c98 100644 --- a/docs/services/logging.md +++ b/docs/services/logging.md @@ -60,8 +60,9 @@ Each request then writes one Info record with the message `http request` once it |-----------|-------| | `method` | The request method. | | `pattern` | The matched route, method and path pattern, for example `GET /posts/{id}`. Empty when no route matched. | -| `status` | The response status; a handler that writes without setting one counts as 200. A 5xx written after the client cancelled the request is logged as 499 (client closed request), since the error came from the cancellation and no client received it. | +| `status` | The response status; a handler that writes without setting one counts as 200. A 5xx is logged as 499 (client closed request) only when the client had already gone away when the status was written and the handler did not panic: the error came from the cancellation, and no client received it. A 5xx written before the client went away keeps its status, and a recovered panic is always 500, so a search for 5xx records finds every real server error. | | `duration_ms` | Time spent serving the request, in whole milliseconds. | +| `client_gone` | `true` when the client went away before the request was served (its context ended with `context.Canceled`); absent otherwise. | The record never carries the URL path, the query string, request or response headers or the client address, because tokens often travel in paths and query strings. That holds for a request that reached no route too: a token route requested with another method gets a 405 from the router, and its trailing-slash variant a 404, before any route handler runs, so the path would carry the token. It goes to the published `*slog.Logger` or `slog.Default`, so the redacting handler still applies. Grep for the empty `pattern` to find requests that reached no route; the client's own log (a browser, a proxy) shows which path it asked for. diff --git a/modules/surf/README.md b/modules/surf/README.md index 2bfc482..07ded62 100644 --- a/modules/surf/README.md +++ b/modules/surf/README.md @@ -35,7 +35,7 @@ Use cases: - Optional `surf.LocaleResolver`: a compiled plugin publishes the interface through backpack; surf looks it up without importing the plugin. When present, it may strip an enabled locale prefix before routing and writes a validated code with `towel.WithLocale`. When absent, hosts keep the raw `Accept-Language` header and `surf.LocaleFromPrincipal` overlay. - `surf.LocaleFromPrincipal` switches the request locale to the signed-in user's preferred locale. - Opt-in uploads route: with `storage.uploads.serve` true, `surf.BuildRouter` mounts `GET /{path...}` (owned by `summercms.surf`) on `attach.StaticHandlerPublic`, so a file is served only when its `system_files` row is public, and every response carries `X-Content-Type-Options: nosniff`. The bucket and the database are looked up per request, so `route:list` lists the route without opening either; until `serve` publishes them it answers 404. The route owns the whole prefix: `surf.BuildRouter` fails when a plugin route sits at or under it. -- Opt-in request log: with `http.access_log` true, every request writes one Info record `http request` after it is served, with `method`, `pattern` (the matched route, such as `GET /posts/{id}`), `status` and `duration_ms`. A 5xx written after the client cancelled the request is logged with status 499 (client closed request). An unmatched request (a 404 or 405 from the mux, or a CORS preflight answered before routing) has an empty `pattern`. The URL path, the query string, headers and the client address are never logged, for an unmatched request too: a token route requested with another method answers 405 before any route handler runs. Records go to the app's published `*slog.Logger`, else `slog.Default`, so the [sunscreen](../sunscreen/README.md) redaction still applies. +- Opt-in request log: with `http.access_log` true, every request writes one Info record `http request` after it is served, with `method`, `pattern` (the matched route, such as `GET /posts/{id}`), `status` and `duration_ms`. A request whose client went away adds `client_gone=true`; its 5xx is logged as 499 (client closed request) only when the client had already gone when the status was written and the handler did not panic, so a 5xx written before the cancellation and a recovered panic keep their real status. An unmatched request (a 404 or 405 from the mux, or a CORS preflight answered before routing) has an empty `pattern`. The URL path, the query string, headers and the client address are never logged, for an unmatched request too: a token route requested with another method answers 405 before any route handler runs. Records go to the app's published `*slog.Logger`, else `slog.Default`, so the [sunscreen](../sunscreen/README.md) redaction still applies. - A read-only route table (`surf.Router.Routes`), the admin mount status (`surf.Router.AdminPrefix`) and the `serve` and `route:list` commands. ## Usage diff --git a/modules/surf/accesslog.go b/modules/surf/accesslog.go index 62a059d..afe6fdf 100644 --- a/modules/surf/accesslog.go +++ b/modules/surf/accesslog.go @@ -20,15 +20,18 @@ const accessLogMessage = "http request" // pattern into. A pointer travels in the context, so the pattern reaches // the access log even when stripLocalePrefix hands ServeMux a copied // request whose Pattern the outer middleware never sees. +// recoverJSON and recoverBare set panicked when they recover a panic, so a +// recovered panic is logged as 500 even when the client had gone away. type accessEntry struct { - pattern string + pattern string + panicked bool } type accessEntryKey struct{} // statusClientClosedRequest is nginx's 499 "client closed request": the -// status the access log records for a request whose client went away before -// the handler answered. +// status the access log records for a 5xx the handler wrote after its client +// had gone away, when the error came from that cancellation. const statusClientClosedRequest = 499 // accessLogEnabled reports whether http.access_log is true. @@ -43,22 +46,29 @@ func accessLogEnabled(app *backpack.App) bool { // a token route reached with another method, or a 404 for its trailing-slash // variant, would otherwise carry the token, because share and invitation // tokens travel in paths. The query string, headers and the remote address -// are never logged either. A 5xx written after the client cancelled the -// request (its context ends with context.Canceled) is logged as 499: the -// error came from the cancellation, and no client received it. The logger -// is the app's published *slog.Logger, else slog.Default (which the -// generated main wraps in the redacting sunscreen handler). +// are never logged either. +// +// A request whose client went away (its context ended with context.Canceled +// by the time it was served) gets client_gone=true. Its 5xx is logged as 499 +// only when the context had already ended when the status was written and +// the handler did not panic: a query or call on the cancelled context then +// failed because of the cancellation, and no client received the error. A +// 5xx written before the client went away keeps its status, and a recovered +// panic is always 500, so a search for 5xx records still finds every real +// server error. The logger is the app's published *slog.Logger, else +// slog.Default (which the generated main wraps in the redacting sunscreen +// handler). func accessLog(app *backpack.App, next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { start := time.Now() entry := &accessEntry{} - rec := &statusRecorder{ResponseWriter: w} + rec := &statusRecorder{ResponseWriter: w, ctx: req.Context()} next.ServeHTTP(rec, req.WithContext(context.WithValue(req.Context(), accessEntryKey{}, entry))) status := rec.status if status == 0 { status = http.StatusOK } - if status >= http.StatusInternalServerError && errors.Is(req.Context().Err(), context.Canceled) { + if status >= http.StatusInternalServerError && rec.goneAtStatus && !entry.panicked { status = statusClientClosedRequest } attrs := []slog.Attr{ @@ -67,10 +77,26 @@ func accessLog(app *backpack.App, next http.Handler) http.Handler { slog.Int("status", status), slog.Int64("duration_ms", time.Since(start).Milliseconds()), } + if clientGone(req.Context()) { + attrs = append(attrs, slog.Bool("client_gone", true)) + } accessLogger(app).LogAttrs(req.Context(), slog.LevelInfo, accessLogMessage, attrs...) }) } +// clientGone reports whether ctx ended because the client went away. +func clientGone(ctx context.Context) bool { + return ctx != nil && errors.Is(ctx.Err(), context.Canceled) +} + +// markPanicked records a recovered panic in the request's access log entry, +// when the access log put one into the context. +func markPanicked(req *http.Request) { + if entry, ok := req.Context().Value(accessEntryKey{}).(*accessEntry); ok && entry != nil { + entry.panicked = true + } +} + // accessLogger is the app's published logger, else slog.Default. func accessLogger(app *backpack.App) *slog.Logger { if app != nil { @@ -92,25 +118,31 @@ func recordPattern(pattern string, next http.Handler) http.Handler { }) } -// statusRecorder remembers the first status written; a Write without a -// WriteHeader is a 200. Flush and Unwrap keep http.ResponseController -// working through it. +// statusRecorder remembers the first status written and whether the +// client had already gone away (ctx ended with context.Canceled) at that +// moment; a Write without a WriteHeader is a 200. Flush and Unwrap keep +// http.ResponseController working through it. type statusRecorder struct { http.ResponseWriter - status int + ctx context.Context + status int + goneAtStatus bool +} + +func (w *statusRecorder) record(status int) { + if w.status == 0 { + w.status = status + w.goneAtStatus = clientGone(w.ctx) + } } func (w *statusRecorder) WriteHeader(status int) { - if w.status == 0 { - w.status = status - } + w.record(status) w.ResponseWriter.WriteHeader(status) } func (w *statusRecorder) Write(p []byte) (int, error) { - if w.status == 0 { - w.status = http.StatusOK - } + w.record(http.StatusOK) return w.ResponseWriter.Write(p) } diff --git a/modules/surf/accesslog_test.go b/modules/surf/accesslog_test.go index 0b097ce..d1469e8 100644 --- a/modules/surf/accesslog_test.go +++ b/modules/surf/accesslog_test.go @@ -128,16 +128,63 @@ func TestAccessLogSmoke(t *testing.T) { } } -// A 5xx written after the client cancelled the request is logged as 499; -// a 5xx on a live request keeps its status. +// TestAccessLogClientClosedRequest: a 5xx is logged as 499 only when the +// client had already gone (the request context ended with context.Canceled) +// when the status was written and the handler did not panic. A 5xx written +// before the client went away keeps its status, and a recovered panic is +// always 500, so a grep for 5xx still finds every real server error. Every +// record of a request whose client went away carries client_gone=true. func TestAccessLogClientClosedRequest(t *testing.T) { + type outcome struct { + status float64 + clientGone bool + } for _, tc := range []struct { - name string - cancel bool - want float64 + name string + handler func(cancel context.CancelFunc) http.Handler + want outcome }{ - {"cancelled", true, 499}, - {"live", false, 500}, + {"5xx after the client went away", func(cancel context.CancelFunc) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + cancel() + w.WriteHeader(http.StatusInternalServerError) + }) + }, outcome{499, true}}, + {"live 5xx", func(context.CancelFunc) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + }) + }, outcome{500, false}}, + {"5xx before the client went away", func(cancel context.CancelFunc) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusBadGateway) + cancel() + }) + }, outcome{502, true}}, + {"200 then the client went away", func(cancel context.CancelFunc) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + _, _ = w.Write([]byte("ok")) + cancel() + }) + }, outcome{200, true}}, + {"5xx through the JSON recovery after the client went away", func(cancel context.CancelFunc) http.Handler { + return recordPattern("GET /blog/posts/{id}", recoverJSON(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + cancel() + w.WriteHeader(http.StatusInternalServerError) + }))) + }, outcome{499, true}}, + {"panic after the client went away (JSON group)", func(cancel context.CancelFunc) http.Handler { + return recordPattern("GET /blog/posts/{id}", recoverJSON(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + cancel() + panic("blog: broken") + }))) + }, outcome{500, true}}, + {"panic after the client went away (raw group)", func(cancel context.CancelFunc) http.Handler { + return recordPattern("GET /blog/posts/{id}", recoverBare(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + cancel() + panic("blog: broken") + }))) + }, outcome{500, true}}, } { t.Run(tc.name, func(t *testing.T) { app := backpack.New(writeHTTPConfig(t, "access_log: true\n")) @@ -147,17 +194,16 @@ func TestAccessLogClientClosedRequest(t *testing.T) { } ctx, cancel := context.WithCancel(t.Context()) defer cancel() - h := accessLog(app, http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { - if tc.cancel { - cancel() - } - w.WriteHeader(http.StatusInternalServerError) - })) + h := accessLog(app, tc.handler(cancel)) req := httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil).WithContext(ctx) h.ServeHTTP(httptest.NewRecorder(), req) recs := accessRecords(t, &buf) - if len(recs) != 1 || recs[0]["status"] != tc.want { - t.Fatalf("records=%v, want one with status %v", recs, tc.want) + if len(recs) != 1 { + t.Fatalf("records = %v, want one", recs) + } + gone, hasGone := recs[0]["client_gone"] + if recs[0]["status"] != tc.want.status || hasGone != tc.want.clientGone || (hasGone && gone != true) { + t.Fatalf("record = %v, want status %v client_gone %t", recs[0], tc.want.status, tc.want.clientGone) } }) } diff --git a/modules/surf/router.go b/modules/surf/router.go index 99e7bf0..f31a753 100644 --- a/modules/surf/router.go +++ b/modules/surf/router.go @@ -655,6 +655,7 @@ func recoverJSON(next http.Handler) http.Handler { buffered := newBufferedResponse() defer func() { if rec := recover(); rec != nil { + markPanicked(r) wire.WriteOpaque500(w) return } @@ -669,6 +670,7 @@ func recoverBare(next http.Handler) http.Handler { buffered := newBufferedResponse() defer func() { if rec := recover(); rec != nil { + markPanicked(r) w.WriteHeader(http.StatusInternalServerError) return } diff --git a/scripts/check-phase14.2.sh b/scripts/check-phase14.2.sh index 265ec27..be40ed7 100755 --- a/scripts/check-phase14.2.sh +++ b/scripts/check-phase14.2.sh @@ -185,7 +185,8 @@ run_regex() { } # scan_go_log FILE refuses a silent search fallback or a 5xx request record -# (research G8, D-12). A 499 (client closed the request) is not a 5xx. +# (research G8, D-12). A 499 (the surf access log's status for a 5xx caused +# by the client going away) is not a 5xx; a 5xx with client_gone=true is. scan_go_log() { local file="$1" hits [[ -f "$file" ]] || { @@ -299,11 +300,13 @@ run_self_test() { local dir dir="$(mktemp -d)" printf '%s\n' '[go] level=INFO msg="http request" method=GET pattern="GET /a" status=200 duration_ms=1' \ - '[go] level=INFO msg="http request" method=GET pattern="GET /b" status=499 duration_ms=3' >"$dir/clean.log" + '[go] level=INFO msg="http request" method=GET pattern="GET /b" status=499 duration_ms=3 client_gone=true' >"$dir/clean.log" printf '%s\n' '[go] level=INFO msg="http request" method=GET pattern="GET /a" status=503 duration_ms=1' >"$dir/5xx.log" + printf '%s\n' '[go] level=INFO msg="http request" method=GET pattern="GET /a" status=500 duration_ms=1 client_gone=true' >"$dir/5xx-gone.log" printf '%s\n' '[go] level=WARN msg="album search engine failed" err=timeout' >"$dir/search.log" expect_status go-log-clean 0 scan_go_log "$dir/clean.log" expect_status go-log-5xx 1 scan_go_log "$dir/5xx.log" + expect_status go-log-5xx-client-gone 1 scan_go_log "$dir/5xx-gone.log" expect_status go-log-search 1 scan_go_log "$dir/search.log" expect_status go-log-missing 1 scan_go_log "$dir/absent.log" printf '# tests 9\n# pass 9\n# fail 0\n# cancelled 0\n# skipped 0\n# todo 0\n' >"$dir/tap-clean"