diff --git a/docs/services/logging.md b/docs/services/logging.md index 4b2ea02..456497f 100644 --- a/docs/services/logging.md +++ b/docs/services/logging.md @@ -62,9 +62,8 @@ Each request then writes one Info record with the message `http request` once it | `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. | | `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. | -The record never carries the query string, request or response headers, the client address or the raw path of a matched route, because tokens often travel in paths and query strings. 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 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. ## Panics diff --git a/modules/surf/README.md b/modules/surf/README.md index dff4d32..2bfc482 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). 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). 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 @@ -156,7 +156,7 @@ The generated application `main` wires surf in with `surf.ServeCommand` and `sur | `http.cors.exposed_headers` | empty | Headers sent in `Access-Control-Expose-Headers`. | | `http.cors.max_age` | `0` | Preflight cache time in seconds. | | `http.cors.supports_credentials` | `false` | Sends `Access-Control-Allow-Credentials: true`. | -| `http.access_log` | `false` | Logs one `http request` record per request (method, matched pattern, status, duration in milliseconds; the path without its query only when no route matched). Environment: `SUMMER_HTTP__ACCESS_LOG`. | +| `http.access_log` | `false` | Logs one `http request` record per request (method, matched pattern, status, duration in milliseconds; never the path or query). Environment: `SUMMER_HTTP__ACCESS_LOG`. | | `storage.uploads.serve` | `false` | Mounts the uploads route `GET /{path...}` (prefix default `/storage/uploads`) on `attach.StaticHandlerPublic` with `X-Content-Type-Options: nosniff`. Prefer a separate origin for uploads in production. Environment: `SUMMER_STORAGE__UPLOADS__SERVE`. | ```yaml diff --git a/modules/surf/accesslog.go b/modules/surf/accesslog.go index 387ffd9..62a059d 100644 --- a/modules/surf/accesslog.go +++ b/modules/surf/accesslog.go @@ -38,16 +38,16 @@ func accessLogEnabled(app *backpack.App) bool { // accessLog logs one Info record "http request" per request after it is // served, with method, pattern (the matched route, "" when none matched), -// status and duration_ms (whole milliseconds). Only when no route matched -// (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. 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). +// status and duration_ms (whole milliseconds). The URL path is never +// logged, not even for a request that matched no route: a ServeMux 405 for +// 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). func accessLog(app *backpack.App, next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { start := time.Now() @@ -67,9 +67,6 @@ func accessLog(app *backpack.App, next http.Handler) http.Handler { slog.Int("status", status), slog.Int64("duration_ms", time.Since(start).Milliseconds()), } - if entry.pattern == "" { - attrs = append(attrs, slog.String("path", req.URL.Path)) - } accessLogger(app).LogAttrs(req.Context(), slog.LevelInfo, accessLogMessage, attrs...) }) } diff --git a/modules/surf/accesslog_test.go b/modules/surf/accesslog_test.go index 3afeaae..0b097ce 100644 --- a/modules/surf/accesslog_test.go +++ b/modules/surf/accesslog_test.go @@ -109,11 +109,14 @@ func TestAccessLogSmoke(t *testing.T) { t.Fatalf("records = %d, want 1:\n%s", len(recs), buf.String()) } r = recs[0] - if r["pattern"] != "" || r["status"] != float64(404) || r["path"] != "/acme/missing" { + if r["pattern"] != "" || r["status"] != float64(404) { t.Fatalf("unmatched record = %v", r) } - if strings.Contains(buf.String(), "secret") { - t.Fatalf("unmatched record leaks the query:\n%s", buf.String()) + if _, ok := r["path"]; ok { + t.Fatalf("unmatched record carries path: %v", r) + } + if strings.Contains(buf.String(), "secret") || strings.Contains(buf.String(), "/acme/missing") { + t.Fatalf("unmatched record leaks the path or query:\n%s", buf.String()) } off, offBuf := accessLogRouter(t, false) @@ -235,8 +238,9 @@ func accessRawRecords(t *testing.T, buf *bytes.Buffer) []map[string]any { // TestAccessLog: off, nothing is logged. On, one record per request with // the matched pattern and status for a 200, a handler 404 and a recovered -// panic (500); an unmatched request gets status 404 and its path without -// the query; a locale-prefixed request still records the route pattern; +// panic (500); an unmatched request (a 404, a 405 for a route reached with +// another method, a trailing-slash 404) gets an empty pattern and no path; +// a locale-prefixed request still records the route pattern; // duration_ms is a non-negative integer; no record carries the query // string, a header name or value or the Authorization value; and a // handler's http.ResponseController flush keeps working. @@ -244,21 +248,29 @@ func TestAccessLog(t *testing.T) { type want struct { pattern string status int64 - path string // "" means the record must have no path } cases := []struct { target string code int want want }{ - {"/blog/posts/7?token=query-secret", http.StatusOK, want{"GET /blog/posts/{id}", 200, ""}}, - {"/blog/drafts/9?token=query-secret", http.StatusNotFound, want{"GET /blog/drafts/{id}", 404, ""}}, - {"/blog/broken?token=query-secret", http.StatusInternalServerError, want{"GET /blog/broken", 500, ""}}, - {"/acme/missing?token=query-secret", http.StatusNotFound, want{"", 404, "/acme/missing"}}, - {"/pl/blog/posts/8?token=query-secret", http.StatusOK, want{"GET /blog/posts/{id}", 200, ""}}, + {"/blog/posts/7?token=query-secret", http.StatusOK, want{"GET /blog/posts/{id}", 200}}, + {"/blog/drafts/9?token=query-secret", http.StatusNotFound, want{"GET /blog/drafts/{id}", 404}}, + {"/blog/broken?token=query-secret", http.StatusInternalServerError, want{"GET /blog/broken", 500}}, + {"/acme/missing?token=query-secret", http.StatusNotFound, want{"", 404}}, + {"/pl/blog/posts/8?token=query-secret", http.StatusOK, want{"GET /blog/posts/{id}", 200}}, + // A token route reached with another method (405) or a trailing + // slash (404) matches no route: ServeMux answers before any route + // handler runs, so the path segment must not reach the log. + {"POST /blog/posts/path-secret-405", http.StatusMethodNotAllowed, want{"", 405}}, + {"/blog/posts/path-secret-404/", http.StatusNotFound, want{"", 404}}, } request := func(target string) *http.Request { - req := httptest.NewRequest(http.MethodGet, target, nil) + method := http.MethodGet + if m, rest, ok := strings.Cut(target, " "); ok { + method, target = m, rest + } + req := httptest.NewRequest(method, target, nil) req.Header.Set("Authorization", "Bearer authz-secret-value") req.Header.Set("X-Blog-Probe", "probe-header-value") req.Header.Set("Cookie", "session=cookie-secret-value") @@ -279,7 +291,8 @@ func TestAccessLog(t *testing.T) { buf.Reset() flushErr = context.Canceled rec := httptest.NewRecorder() - h.ServeHTTP(rec, request(tc.target)) + req := request(tc.target) + h.ServeHTTP(rec, req) if rec.Code != tc.code { t.Fatalf("GET %s = %d, want %d", tc.target, rec.Code, tc.code) } @@ -292,7 +305,7 @@ func TestAccessLog(t *testing.T) { } r := recs[0] status, err := r["status"].(json.Number).Int64() - if err != nil || r["method"] != "GET" || r["pattern"] != tc.want.pattern || status != tc.want.status || r["level"] != "INFO" { + if err != nil || r["method"] != req.Method || r["pattern"] != tc.want.pattern || status != tc.want.status || r["level"] != "INFO" { t.Fatalf("GET %s: record %v, want pattern %q status %d", tc.target, r, tc.want.pattern, tc.want.status) } d, ok := r["duration_ms"].(json.Number) @@ -302,17 +315,13 @@ func TestAccessLog(t *testing.T) { if n, err := strconv.ParseInt(d.String(), 10, 64); err != nil || n < 0 { t.Fatalf("GET %s: duration_ms %q is not a non-negative integer", tc.target, d) } - path, hasPath := r["path"] - if tc.want.path == "" && hasPath { - t.Fatalf("GET %s: a matched record carries path: %v", tc.target, r) - } - if tc.want.path != "" && path != tc.want.path { - t.Fatalf("GET %s: path = %v, want %q", tc.target, path, tc.want.path) + if _, hasPath := r["path"]; hasPath { + t.Fatalf("GET %s: the record carries path: %v", tc.target, r) } for _, leak := range []string{ "query-secret", "token=", "authz-secret-value", "Authorization", "Bearer", "X-Blog-Probe", "probe-header-value", "cookie-secret-value", "Cookie", - "/blog/posts/7", "/blog/posts/8", "/pl/", + "/blog/posts/7", "/blog/posts/8", "/pl/", "path-secret", "/acme/missing", } { if strings.Contains(buf.String(), leak) { t.Fatalf("GET %s: the log carries %q:\n%s", tc.target, leak, buf.String())