summercms/modules/surf/accesslog.go

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 }