golem15/summercms
3
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix(14.2): WR-02 499 only for a 5xx caused by the client going away

Browse Source 
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.
This commit is contained in:
Jakub Zych
2026-10-12 11:19:12 +02:00
parent fbcfaaf05f
commit c30145ed25
6 changed files with 123 additions and 39 deletions
Download Patch File Download Diff File Expand all files Collapse all files

3
docs/services/logging.md
View File

@@ -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.

2
modules/surf/README.md
View File

@@ -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 <storage.uploads.public_path_prefix>/{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

72
modules/surf/accesslog.go
View File

@@ -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)
}

76
modules/surf/accesslog_test.go
View File

@@ -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)
}
})
}

2
modules/surf/router.go
View File

@@ -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
}

7
scripts/check-phase14.2.sh
View File

@@ -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"