diff --git a/docs/services/logging.md b/docs/services/logging.md index ea6cdef..4b2ea02 100644 --- a/docs/services/logging.md +++ b/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. | diff --git a/modules/surf/README.md b/modules/surf/README.md index 634df85..4cd3e1c 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. 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 diff --git a/modules/surf/accesslog.go b/modules/surf/accesslog.go index af83603..387ffd9 100644 --- a/modules/surf/accesslog.go +++ b/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), diff --git a/modules/surf/accesslog_test.go b/modules/surf/accesslog_test.go index acd1fe2..6b1ba98 100644 --- a/modules/surf/accesslog_test.go +++ b/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) + } + }) + } +}