package surf import ( "context" "errors" "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. // 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 panicked bool } type accessEntryKey struct{} // statusClientClosedRequest is nginx's 499 "client closed request": the // 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. 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). 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 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, 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 && rec.goneAtStatus && !entry.panicked { status = statusClientClosedRequest } 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 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 { 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 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 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) { w.record(status) w.ResponseWriter.WriteHeader(status) } func (w *statusRecorder) Write(p []byte) (int, error) { w.record(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 }