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. SWWAF_METRICS_TOP_N
bounds the series by country, the rest counted as other.

Judgement call: a request answered at smallwebwaf's own endpoints is
neither forwarded nor refused in the client's history.
Deviation: go.mod and go.sum written by hand from the module proxy and
sum.golang.org, 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",
 		})
 	}
 }