fix(14.2-03): access log records a cancelled request's 5xx as 499

A client that goes away mid-request cancels the context; a handler then
fails on context.Canceled and writes a 500 nobody receives. The request
log now records it as 499 (client closed request) so a grep for 5xx shows
real server errors only.

docs/services/logging.md

@@ -60,7 +60,7 @@ 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. |
+| `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. |
 | `duration_ms` | Time spent serving the request, in whole milliseconds. |
 | `path` | Only when no route matched (a 404 or 405 from the router, or a CORS preflight answered before routing): the URL path without the query string. |
 

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 <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. A plugin route on the same pattern fails boot as a duplicate.
-- 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`. Only an unmatched request (a 404 or 405 from the mux, or a CORS preflight answered before routing) adds `path`, without the query string. The query string, headers, the client address and a matched route's raw path are never logged. 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 5xx written after the client cancelled the request is logged with status 499 (client closed request). Only an unmatched request (a 404 or 405 from the mux, or a CORS preflight answered before routing) adds `path`, without the query string. The query string, headers, the client address and a matched route's raw path are never logged. 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

modules/surf/accesslog.go

@@ -2,6 +2,7 @@ package surf
 
 import (
 	"context"
+	"errors"
 	"log/slog"
 	"net/http"
 	"time"
@@ -25,6 +26,11 @@ type accessEntry struct {
 
 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.
+const statusClientClosedRequest = 499
+
 // accessLogEnabled reports whether http.access_log is true.
 func accessLogEnabled(app *backpack.App) bool {
 	return app != nil && app.Config != nil && app.Config.Bool(accessLogKey)
@@ -36,7 +42,10 @@ func accessLogEnabled(app *backpack.App) bool {
 // (a ServeMux 404 or 405, or a CORS preflight answered before routing) is
 // path added, set to the URL path without the query string. The query
 // string, headers, the remote address and a matched route's raw path are
-// never logged: share and invitation tokens travel in paths. The logger is
+// never logged: share and invitation tokens travel in paths. 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).
 func accessLog(app *backpack.App, next http.Handler) http.Handler {
@@ -49,6 +58,9 @@ func accessLog(app *backpack.App, next http.Handler) http.Handler {
 		if status == 0 {
 			status = http.StatusOK
 		}
+		if status >= http.StatusInternalServerError && errors.Is(req.Context().Err(), context.Canceled) {
+			status = statusClientClosedRequest
+		}
 		attrs := []slog.Attr{
 			slog.String("method", req.Method),
 			slog.String("pattern", entry.pattern),

modules/surf/accesslog_test.go

@@ -2,6 +2,7 @@ package surf
 
 import (
 	"bytes"
+	"context"
 	"encoding/json"
 	"log/slog"
 	"net/http"
@@ -122,3 +123,38 @@ func TestAccessLogSmoke(t *testing.T) {
 		t.Fatalf("http.access_log off still logged:\n%s", offBuf.String())
 	}
 }
+
+// A 5xx written after the client cancelled the request is logged as 499;
+// a 5xx on a live request keeps its status.
+func TestAccessLogClientClosedRequest(t *testing.T) {
+	for _, tc := range []struct {
+		name   string
+		cancel bool
+		want   float64
+	}{
+		{"cancelled", true, 499},
+		{"live", false, 500},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			app := backpack.New(writeHTTPConfig(t, "access_log: true\n"))
+			var buf bytes.Buffer
+			if err := app.Publish(slog.New(slog.NewJSONHandler(&buf, nil))); err != nil {
+				t.Fatal(err)
+			}
+			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)
+			}))
+			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)
+			}
+		})
+	}
+}