Felis/internal/api/observe.go

package api

import (
	"context"
	"log/slog"
	"net/http"
	"os"
	"strconv"
	"strings"
	"time"

	"github.com/prometheus/client_golang/prometheus"
)

// Request observability: one access-log line and two series per API request.
//
// The route label is the matched ServeMux pattern ("/api/v1/servers/{name}"),
// never the raw path, so a scan of random URLs cannot grow the series set; a
// request no route matched is "unmatched". The method label is folded the same
// way (methodLabel). Stream routes (text/event-stream) count toward the request
// total but stay out of the duration histogram, where an attachment that lasts
// half an hour would only bury the latency of everything else.

var (
	httpRequestsTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
		Namespace: "felis",
		Name:      "http_requests_total",
		Help:      "API requests served, by face, method, route pattern and status code.",
	}, []string{"face", "method", "route", "code"})

	httpRequestDuration = prometheus.NewHistogramVec(prometheus.HistogramOpts{
		Namespace: "felis",
		Name:      "http_request_duration_seconds",
		Help:      "API request latency, by face and route pattern (streams excluded).",
		Buckets:   []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10, 30},
	}, []string{"face", "route"})
)

// defaultAccessLog writes logfmt lines to stderr, next to the API's other logs.
var defaultAccessLog = slog.New(slog.NewTextHandler(os.Stderr, nil))

// routeUnmatched labels a request no route pattern matched.
const routeUnmatched = "unmatched"

// reqInfo is filled in by the handlers a request passes through, for observe to
// read once the response is done: the matched route, and the principal once the
// face's guard has resolved one.
type reqInfo struct {
	route     string
	principal string
}

func reqInfoFrom(ctx context.Context) *reqInfo {
	info, _ := ctx.Value(ctxKeyReqInfo).(*reqInfo)
	return info
}

// noteRoute records the matched route pattern (without its method).
func noteRoute(r *http.Request, pattern string) {
	if info := reqInfoFrom(r.Context()); info != nil {
		if _, path, ok := strings.Cut(pattern, " "); ok {
			pattern = path
		}
		info.route = pattern
	}
}

// tagRoute wraps a route's handler so the request records its pattern and, on
// the authenticated faces, who made it.
func tagRoute(pattern string, h http.HandlerFunc) http.HandlerFunc {
	return func(w http.ResponseWriter, r *http.Request) {
		noteRoute(r, pattern)
		if info := reqInfoFrom(r.Context()); info != nil {
			if p := principalFromContext(r.Context()); p != nil {
				info.principal = p.UserID
			}
		}
		h(w, r)
	}
}

// methodLabel folds anything but the methods the API serves into one value.
func methodLabel(m string) string {
	switch m {
	case http.MethodGet, http.MethodHead, http.MethodPost, http.MethodPut,
		http.MethodPatch, http.MethodDelete, http.MethodOptions:
		return m
	}
	return "OTHER"
}

// quietRoute reports whether a successful request is left out of the access log:
// the probes and the scrape, which arrive every few seconds and say nothing.
func quietRoute(route string, status int) bool {
	if status >= 400 {
		return false
	}
	switch route {
	case "/healthz", "/readyz", "/metrics":
		return true
	}
	return false
}

// observe records every request that reaches face: the access-log line and the
// felis_http_* series.
func (a *API) observe(face string, next http.Handler) http.Handler {
	logger := a.AccessLog
	if logger == nil {
		logger = defaultAccessLog
	}
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		start := time.Now()
		info := &reqInfo{}
		rec := &statusRecorder{ResponseWriter: w}
		next.ServeHTTP(rec, r.WithContext(context.WithValue(r.Context(), ctxKeyReqInfo, info)))

		status := rec.status
		if status == 0 {
			status = http.StatusOK
		}
		route := info.route
		if route == "" {
			route = routeUnmatched
		}
		elapsed := time.Since(start)
		httpRequestsTotal.WithLabelValues(face, methodLabel(r.Method), route, strconv.Itoa(status)).Inc()
		if !strings.HasPrefix(rec.Header().Get("Content-Type"), "text/event-stream") {
			httpRequestDuration.WithLabelValues(face, route).Observe(elapsed.Seconds())
		}
		if quietRoute(route, status) {
			return
		}
		logger.LogAttrs(r.Context(), slog.LevelInfo, "request",
			slog.String("face", face),
			slog.String("method", r.Method),
			slog.String("route", route),
			slog.String("path", r.URL.Path),
			slog.Int("status", status),
			slog.Int64("duration_ms", elapsed.Milliseconds()),
			slog.Int64("bytes", rec.bytes),
			slog.String("request_id", requestIDFromContext(r.Context())),
			slog.String("principal", info.principal),
		)
	})
}

// statusRecorder notes the status and size of a response. It passes flushes
// through with their error (the SSE relay's write-deadline guard depends on
// seeing a failed flush) and unwraps for http.ResponseController, so deadlines
// still reach the connection.
type statusRecorder struct {
	http.ResponseWriter
	status int
	bytes  int64
}

func (s *statusRecorder) WriteHeader(code int) {
	if s.status == 0 {
		s.status = code
	}
	s.ResponseWriter.WriteHeader(code)
}

func (s *statusRecorder) Write(p []byte) (int, error) {
	if s.status == 0 {
		s.status = http.StatusOK
	}
	n, err := s.ResponseWriter.Write(p)
	s.bytes += int64(n)
	return n, err
}

func (s *statusRecorder) FlushError() error {
	if s.status == 0 {
		s.status = http.StatusOK
	}
	return http.NewResponseController(s.ResponseWriter).Flush()
}

func (s *statusRecorder) Flush() { _ = s.FlushError() }

func (s *statusRecorder) Unwrap() http.ResponseWriter { return s.ResponseWriter }