Serve Prometheus metrics behind SWWAF_METRICS_TOKEN (closes #23)

GET /_smallwebwaf/metrics answers in the Prometheus text format for a
request carrying SWWAF_METRICS_TOKEN, 401 without it and 404 while it is
unset. Every request under /_smallwebwaf/ but the health check now goes
through the checks and is answered where it would be forwarded, 404 for
any path but the metrics, so none reaches the app. In the client's
history a 401 counts as refused, the metrics and the 404s as neither.
SWWAF_METRICS_TOP_N bounds the series by country, the rest counted as
other.

Deviation: go.mod and go.sum written by hand, as go runs only through
make.
Deviation: no metrics yet for state files read again after an edit or
edits set aside; that work is not merged.

Model: opus-5-5

internal/proxy/request.go

@@ -22,11 +22,13 @@ const flushAfterEachWrite time.Duration = -1
 
 // refusal is smallwebwaf refusing a request, or refusing to go on with it:
 // the status the client is answered if the response has not started yet,
-// 0 to close the connection without an answer, and the action the log
-// line names.
+// 0 to close the connection without an answer, the action the log line
+// names, and the setting whose size or time limit the request passed, if
+// that is why.
 type refusal struct {
 	status int
 	action string
+	limit  string
 }
 
 // request is one request on its way through smallwebwaf, from the moment
@@ -65,9 +67,11 @@ type request struct {
 	requestSent time.Time
 }
 
-// newRequest starts handling r: it notes the time and works out the
-// client.
+// newRequest starts handling r: it notes the time, counts the request as
+// under way, and works out the client.
 func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
+	h.metrics.RequestStarted()
+
 	start := time.Now()
 	peer := peerAddress(r)
 	trusted := h.config.TrustedProxies
@@ -141,6 +145,7 @@ func (rq *request) check(ctx context.Context) *refusal {
 		return &refusal{
 			status: http.StatusRequestEntityTooLarge,
 			action: requestlog.ActionTooLarge,
+			limit:  "SWWAF_REQUEST_MAX_BYTES",
 		}
 	}
 
@@ -206,7 +211,11 @@ func (rq *request) modifyResponse(res *http.Response) error {
 
 	maxBytes := rq.h.config.ResponseMaxBytes
 	if maxBytes > 0 && res.Body != http.NoBody && res.ContentLength > maxBytes {
-		rq.refuse(refusal{status: http.StatusBadGateway, action: requestlog.ActionTooLarge})
+		rq.refuse(refusal{
+			status: http.StatusBadGateway,
+			action: requestlog.ActionTooLarge,
+			limit:  "SWWAF_RESPONSE_MAX_BYTES",
+		})
 
 		return errResponseTooLarge
 	}
@@ -278,7 +287,8 @@ func (rq *request) refuse(r refusal) {
 	rq.cancel()
 }
 
-// finish ends the request's timeouts and writes its log line.
+// finish ends the request's timeouts, counts it in the metrics and writes
+// its log line.
 func (rq *request) finish() {
 	rq.stopTimers()
 
@@ -295,24 +305,37 @@ func (rq *request) finish() {
 		line.RequestBytes = rq.body.bytes.Load()
 	}
 
+	// limit is the setting whose size or time limit the request passed.
+	var limit string
+
 	switch {
 	case refused != nil:
 		line.Action = refused.action
+		limit = refused.limit
 	case errors.Is(rq.out.err, os.ErrDeadlineExceeded):
 		// The client took longer than SWWAF_CLIENT_RESPONSE_TIMEOUT to
 		// take the response.
 		line.Action = requestlog.ActionTimedOut
+		limit = "SWWAF_CLIENT_RESPONSE_TIMEOUT"
 	case !rq.complete && (rq.out.err != nil || rq.in.Context().Err() != nil):
 		line.Aborted = true
 	}
 
 	now := time.Now()
-	line.DurationTotal = requestlog.Milliseconds(now.Sub(rq.start))
+	duration := now.Sub(rq.start)
+	line.DurationTotal = requestlog.Milliseconds(duration)
+
+	var upstreamDuration time.Duration
 
 	if !rq.upstreamStart.IsZero() {
-		line.DurationUpstreamTotal = requestlog.Milliseconds(now.Sub(rq.upstreamStart))
+		upstreamDuration = now.Sub(rq.upstreamStart)
+		line.DurationUpstreamTotal = requestlog.Milliseconds(upstreamDuration)
 	}
 
+	// Counted before the log line is written, so that the metrics count
+	// every request whose line is out.
+	rq.h.metrics.RequestEnded(line, limit, duration, upstreamDuration)
+
 	err := requestlog.Write(rq.h.requestLog, line)
 	if err != nil {
 		rq.h.processLog.Error("writing the request log failed", "error", err.Error())
@@ -327,9 +350,12 @@ func (rq *request) addToHistory() {
 		requestBytes = rq.body.bytes.Load()
 	}
 
+	forwarded := !rq.upstreamStart.IsZero()
+
 	rq.h.limiter.AddToHistory(clientGroup(rq.client), rq.h.now(), ratelimit.Request{
 		Country:       rq.line.Country,
-		Forwarded:     !rq.upstreamStart.IsZero(),
+		Forwarded:     forwarded,
+		Refused:       !forwarded && rq.refused.Load() != nil,
 		Status:        rq.out.status,
 		RequestBytes:  requestBytes,
 		ResponseBytes: rq.out.bytes,
@@ -369,21 +395,26 @@ func (rq *request) startRequestTimers() {
 
 	if rq.body != nil && rq.h.config.ClientRequestTimeout > 0 {
 		rq.clientRequestTimer = time.AfterFunc(
-			time.Until(rq.clientRequestDeadline()), rq.requestTimedOut)
+			time.Until(rq.clientRequestDeadline()), func() {
+				rq.requestTimedOut("SWWAF_CLIENT_REQUEST_TIMEOUT")
+			})
 	}
 
 	timeout := rq.h.config.UpstreamRequestTimeout
 	if timeout > 0 {
-		rq.upstreamRequestTimer = time.AfterFunc(timeout, rq.requestTimedOut)
+		rq.upstreamRequestTimer = time.AfterFunc(timeout, func() {
+			rq.requestTimedOut("SWWAF_UPSTREAM_REQUEST_TIMEOUT")
+		})
 	}
 }
 
-// requestTimedOut is called when a request timeout runs out while the
-// request is still on its way to the app. The answer names the side
-// smallwebwaf was waiting on at that moment: 408 when it was waiting for
-// the client to send more of its body, 504 when it was waiting for the
-// app to be reached or to take what it had.
-func (rq *request) requestTimedOut() {
+// requestTimedOut is called when limit, SWWAF_CLIENT_REQUEST_TIMEOUT or
+// SWWAF_UPSTREAM_REQUEST_TIMEOUT, runs out while the request is still on
+// its way to the app. The answer names the side smallwebwaf was waiting
+// on at that moment: 408 when it was waiting for the client to send more
+// of its body, 504 when it was waiting for the app to be reached or to
+// take what it had.
+func (rq *request) requestTimedOut(limit string) {
 	rq.mu.Lock()
 	defer rq.mu.Unlock()
 
@@ -395,6 +426,7 @@ func (rq *request) requestTimedOut() {
 		rq.refuse(refusal{
 			status: http.StatusGatewayTimeout,
 			action: requestlog.ActionTimedOut,
+			limit:  limit,
 		})
 
 		return
@@ -403,6 +435,7 @@ func (rq *request) requestTimedOut() {
 	rq.refuse(refusal{
 		status: http.StatusRequestTimeout,
 		action: requestlog.ActionTimedOut,
+		limit:  limit,
 	})
 	// The transport gives up on the app only once its Read of the
 	// client's body returns, so that Read is ended now. The lock keeps
@@ -452,6 +485,7 @@ func (rq *request) responseTimedOut() {
 		rq.refuse(refusal{
 			status: http.StatusGatewayTimeout,
 			action: requestlog.ActionTimedOut,
+			limit:  "SWWAF_UPSTREAM_RESPONSE_TIMEOUT",
 		})
 	}
 }