feat(14.2-01): opt-in http.access_log request log in surf

- one Info record "http request" per request with method, matched route
  pattern, status and duration_ms; path without the query only when no
  route matched
- the matched route records its pattern through a request-scoped entry,
  so locale prefix rewrites do not hide it
- logs through the published *slog.Logger or slog.Default; off by default
- surf README, logging and configuration docs describe the key

docs/services/logging.md

@@ -45,6 +45,27 @@ A plugin resolves a `*slog.Logger` from the application with `backpack.Lookup` a
 
 Redaction is a safety net for mistakes, not a way to log secrets on purpose. Log identifiers and outcomes: the record id, the vendor, the status code, how long it took. Never log request arguments, tokens, credentials or request and response bodies, which can carry personal data the patterns do not recognise.
 
+## Request log
+
+The router can log every request. It is off by default; turn it on with the `http.access_log` key (environment `SUMMER_HTTP__ACCESS_LOG=true`):
+
+```yaml
+# config/http.yaml
+access_log: true
+```
+
+Each request then writes one Info record with the message `http request` once it has been served:
+
+| Attribute | Value |
+|-----------|-------|
+| `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. |
+| `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.
+
 ## Panics
 
 The router recovers a panicking handler and answers with an opaque 500: the JSON groups send `{"error":true,"message":"Internal server error"}` and the raw groups an empty body. The panic value never reaches the client. See [Routing](routing.md).

docs/setup/configuration.md

@@ -53,6 +53,7 @@ These are the keys most applications set. Each module's reference page lists all
 | `app.locale`, `app.fallback_locale` | Default and fallback translation locales. | [phrasebook](../../modules/phrasebook/README.md) |
 | `http.body_limits.default_bytes`, `http.body_limits.upload_bytes` | Request body limits. Required by `serve` and `route:list`. | [surf](../../modules/surf/README.md) |
 | `http.cors.*`, `http.trusted_proxies` | CORS and the proxies whose forwarded client IP is trusted. | [surf](../../modules/surf/README.md) |
+| `http.access_log` | Logs one record per request with method, matched route pattern, status and duration. Defaults to `false`. | [surf](../../modules/surf/README.md) |
 | `storage.uploads.bucket_url` | Uploads bucket, `file://` or `mem://`. Required by `serve`. | [lagoon](../../modules/lagoon/README.md) |
 | `storage.uploads.serve` | Mounts `attach.StaticHandlerPublic` under `storage.uploads.public_path_prefix` with `X-Content-Type-Options: nosniff`. Defaults to `false`. | [surf](../../modules/surf/README.md) |
 | `admin.jwt.secret` | Secret for admin tokens. Required as soon as a plugin registers an admin controller. | [cabana](../../modules/cabana/README.md) |

modules/surf/README.md

@@ -35,6 +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.
 - A read-only route table (`surf.Router.Routes`), the admin mount status (`surf.Router.AdminPrefix`) and the `serve` and `route:list` commands.
 
 ## Usage
@@ -155,6 +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`. |
 | `storage.uploads.serve` | `false` | Mounts the uploads route `GET <storage.uploads.public_path_prefix>/{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

modules/surf/accesslog.go

@@ -0,0 +1,114 @@
+package surf
+
+import (
+	"context"
+	"log/slog"
+	"net/http"
+	"time"
+
+	"git.golem15.com/golem15/summercms/modules/backpack"
+)
+
+// accessLogKey is the config key that turns the request log on.
+const accessLogKey = "http.access_log"
+
+// accessLogMessage is the message of every request log record.
+const accessLogMessage = "http request"
+
+// accessEntry is the request-scoped slot the matched route writes its
+// 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.
+type accessEntry struct {
+	pattern string
+}
+
+type accessEntryKey struct{}
+
+// accessLogEnabled reports whether http.access_log is true.
+func accessLogEnabled(app *backpack.App) bool {
+	return app != nil && app.Config != nil && app.Config.Bool(accessLogKey)
+}
+
+// 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. 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}
+		next.ServeHTTP(rec, req.WithContext(context.WithValue(req.Context(), accessEntryKey{}, entry)))
+		status := rec.status
+		if status == 0 {
+			status = http.StatusOK
+		}
+		attrs := []slog.Attr{
+			slog.String("method", req.Method),
+			slog.String("pattern", entry.pattern),
+			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...)
+	})
+}
+
+// accessLogger is the app's published logger, else slog.Default.
+func accessLogger(app *backpack.App) *slog.Logger {
+	if app != nil {
+		if log, ok := app.Lookup[*slog.Logger](); ok && log != nil {
+			return log
+		}
+	}
+	return slog.Default()
+}
+
+// recordPattern stores pattern in the request's access log entry, when the
+// access log put one into the context, before serving the route.
+func recordPattern(pattern string, next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		if entry, ok := req.Context().Value(accessEntryKey{}).(*accessEntry); ok && entry != nil {
+			entry.pattern = pattern
+		}
+		next.ServeHTTP(w, req)
+	})
+}
+
+// statusRecorder remembers the first status written; a Write without a
+// WriteHeader is a 200. Flush and Unwrap keep http.ResponseController
+// working through it.
+type statusRecorder struct {
+	http.ResponseWriter
+	status int
+}
+
+func (w *statusRecorder) WriteHeader(status int) {
+	if w.status == 0 {
+		w.status = status
+	}
+	w.ResponseWriter.WriteHeader(status)
+}
+
+func (w *statusRecorder) Write(p []byte) (int, error) {
+	if w.status == 0 {
+		w.status = http.StatusOK
+	}
+	return w.ResponseWriter.Write(p)
+}
+
+func (w *statusRecorder) Flush() {
+	if f, ok := w.ResponseWriter.(http.Flusher); ok {
+		f.Flush()
+	}
+}
+
+func (w *statusRecorder) Unwrap() http.ResponseWriter { return w.ResponseWriter }

modules/surf/accesslog_test.go

@@ -0,0 +1,124 @@
+package surf
+
+import (
+	"bytes"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"git.golem15.com/golem15/summercms/modules/backpack"
+	"git.golem15.com/golem15/summercms/modules/pact"
+	"git.golem15.com/golem15/summercms/modules/party"
+)
+
+// blogPostsPlugin serves GET /blog/posts/{id}.
+type blogPostsPlugin struct{}
+
+func (blogPostsPlugin) ID() string                   { return "acme.blog" }
+func (blogPostsPlugin) Requires() []string           { return nil }
+func (blogPostsPlugin) Register(*backpack.App) error { return nil }
+func (blogPostsPlugin) Boot(*backpack.App) error     { return nil }
+func (blogPostsPlugin) Routes(r pact.Router) error {
+	r.Group("/blog", nil, func(g pact.Router) {
+		g.Get("/posts/{id}", func(w http.ResponseWriter, _ *http.Request) {
+			w.Header().Set("Content-Type", "application/json")
+			_, _ = w.Write([]byte(`{"id":7}`))
+		})
+	})
+	return nil
+}
+
+// accessLogRouter assembles the blog plugin with http.access_log set to on
+// and a published JSON logger writing into the returned buffer.
+func accessLogRouter(t *testing.T, on bool) (http.Handler, *bytes.Buffer) {
+	t.Helper()
+	y := "body_limits:\n  default_bytes: 1024\n  upload_bytes: 1024\n"
+	if on {
+		y += "access_log: true\n"
+	}
+	app := backpack.New(writeHTTPConfig(t, y))
+	var buf bytes.Buffer
+	if err := app.Publish(slog.New(slog.NewJSONHandler(&buf, nil))); err != nil {
+		t.Fatal(err)
+	}
+	h, err := Assemble(app, []party.Plugin{blogPostsPlugin{}})
+	if err != nil {
+		t.Fatal(err)
+	}
+	return h, &buf
+}
+
+// accessRecords decodes the "http request" records in buf.
+func accessRecords(t *testing.T, buf *bytes.Buffer) []map[string]any {
+	t.Helper()
+	var out []map[string]any
+	for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
+		if line == "" {
+			continue
+		}
+		var rec map[string]any
+		if err := json.Unmarshal([]byte(line), &rec); err != nil {
+			t.Fatalf("log line %q: %v", line, err)
+		}
+		if rec["msg"] == accessLogMessage {
+			out = append(out, rec)
+		}
+	}
+	return out
+}
+
+func TestAccessLogSmoke(t *testing.T) {
+	h, buf := accessLogRouter(t, true)
+
+	rec := httptest.NewRecorder()
+	h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/blog/posts/7?token=secret", nil))
+	if rec.Code != http.StatusOK {
+		t.Fatalf("GET /blog/posts/7 = %d", rec.Code)
+	}
+	recs := accessRecords(t, buf)
+	if len(recs) != 1 {
+		t.Fatalf("records = %d, want 1:\n%s", len(recs), buf.String())
+	}
+	r := recs[0]
+	if r["method"] != "GET" || r["pattern"] != "GET /blog/posts/{id}" || r["status"] != float64(200) || r["level"] != "INFO" {
+		t.Fatalf("matched record = %v", r)
+	}
+	if _, ok := r["duration_ms"].(float64); !ok {
+		t.Fatalf("matched record has no duration_ms: %v", r)
+	}
+	if _, ok := r["path"]; ok {
+		t.Fatalf("matched record carries path: %v", r)
+	}
+	if strings.Contains(buf.String(), "secret") || strings.Contains(buf.String(), "/blog/posts/7") {
+		t.Fatalf("matched record leaks the raw path or query:\n%s", buf.String())
+	}
+
+	buf.Reset()
+	rec = httptest.NewRecorder()
+	h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/acme/missing?token=secret", nil))
+	if rec.Code != http.StatusNotFound {
+		t.Fatalf("GET /acme/missing = %d", rec.Code)
+	}
+	recs = accessRecords(t, buf)
+	if len(recs) != 1 {
+		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" {
+		t.Fatalf("unmatched record = %v", r)
+	}
+	if strings.Contains(buf.String(), "secret") {
+		t.Fatalf("unmatched record leaks the query:\n%s", buf.String())
+	}
+
+	off, offBuf := accessLogRouter(t, false)
+	for _, target := range []string{"/blog/posts/7", "/acme/missing"} {
+		off.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, target, nil))
+	}
+	if offBuf.Len() != 0 {
+		t.Fatalf("http.access_log off still logged:\n%s", offBuf.String())
+	}
+}

modules/surf/router.go

@@ -378,7 +378,11 @@ func (r *Router) compile() (http.Handler, error) {
 	if err := registerOverlapFamilies(mux, r.routes, handlers, families); err != nil {
 		return nil, err
 	}
-	return r.stripLocalePrefix(pathScopedCORS(r.corsCfg, mux)), nil
+	h := r.stripLocalePrefix(pathScopedCORS(r.corsCfg, mux))
+	if accessLogEnabled(r.app) {
+		h = accessLog(r.app, h)
+	}
+	return h, nil
 }
 
 // handleRoute registers a route, converting a ServeMux conflict panic into an error.
@@ -445,6 +449,8 @@ func (r *Router) wrap(rt route) (http.Handler, error) {
 	} else {
 		h = recoverJSON(h)
 	}
+	// Outermost: name the matched route for the access log (accesslog.go).
+	h = recordPattern(rt.method+" "+rt.path, h)
 	return h, nil
 }