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

README.md

@@ -284,9 +284,10 @@ entries by client address, with times in UTC.
 - `clients.json`: each client's two buckets in the minute, the hour and the day,
   and its history: when it was first and last seen, its country as last looked
   up and when, its requests, how many were forwarded and how many refused (one
-  `smallwebwaf` answered at its own endpoints is neither), the body bytes in
+  `smallwebwaf` answered at its own endpoints is neither, unless it was refused
-  each direction, its responses by status class and its offences by kind. Each
+  with `401` for a missing or wrong token), the body bytes in each direction,
-  client is on a line of its own, so `grep` shows everything about one.
+  its responses by status class and its offences by kind. Each client is on a
+  line of its own, so `grep` shows everything about one.
 - `lookups.json`: GeoJS's answers, one to a line, with when GeoJS gave each and
   when it was last used.
 
@@ -342,9 +343,11 @@ other request. No metric carries a client's address.
   series of their own, and the others are counted as `other`. A country that
   drops out of them loses its series, and its later requests count as `other`;
   one that comes into them gets a series that counts from then on.
-- `smallwebwaf_geojs_requests_total`, `smallwebwaf_geojs_failures_total`, and
+- `smallwebwaf_geojs_requests_total`: the requests to GeoJS;
-  `smallwebwaf_geojs_unanswered_total`: the requests whose client counted as
+  `smallwebwaf_geojs_failures_total`: those that failed, an answer that leaves
-  coming from an unknown country because GeoJS had not answered in time.
+  out an address asked about included; and `smallwebwaf_geojs_unanswered_total`:
+  the requests whose client counted as coming from an unknown country because
+  GeoJS had not answered about it in time.
 - `smallwebwaf_tracked_clients`: the clients in the table of clients.
 - `smallwebwaf_state_file_writes_total`,
   `smallwebwaf_state_file_write_failures_total`,

go.mod

@@ -10,6 +10,7 @@ require (
 require (
 	github.com/beorn7/perks v1.0.1 // indirect
 	github.com/cespare/xxhash/v2 v2.3.0 // indirect
+	github.com/kylelemons/godebug v1.1.0 // indirect
 	github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect
 	github.com/prometheus/client_model v0.6.2 // indirect
 	github.com/prometheus/common v0.70.1 // indirect

internal/lookup/lookup_test.go

@@ -13,6 +13,7 @@ import (
 	"testing/synctest"
 	"time"
 
+	"github.com/prometheus/client_golang/prometheus/testutil"
 	"sneak.berlin/go/smallwebwaf/internal/lookup"
 	"sneak.berlin/go/smallwebwaf/internal/metrics"
 )
@@ -350,6 +351,40 @@ func TestAtMost10000ClientsWait(t *testing.T) {
 	})
 }
 
+func TestClientsWithoutAnAnswerAreCounted(t *testing.T) {
+	t.Parallel()
+
+	synctest.Test(t, func(t *testing.T) {
+		m := metrics.New(1)
+		g := lookup.New(lookup.Params{
+			URL:        lookup.URL,
+			Now:        time.Now,
+			ProcessLog: slog.New(slog.DiscardHandler),
+			Metrics:    m,
+		})
+		g.SetTransport(&standIn{answers: failing})
+
+		clients := newClients()
+
+		// GeoJS fails, so the first client goes without an answer, and GeoJS
+		// is left alone for a second, which does not pass in this test.
+		wantCountry(t, g, clients(), "")
+		wantUnanswered(t, m, 1)
+
+		// Meanwhile each new client goes without one at once, while there is
+		// room for it among the 10,000 that may wait.
+		for range 9999 {
+			wantCountry(t, g, clients(), "")
+		}
+
+		wantUnanswered(t, m, 10000)
+
+		// One more, for which there is no room, goes without one too.
+		wantCountry(t, g, clients(), "")
+		wantUnanswered(t, m, 10001)
+	})
+}
+
 // How the stand-in for GeoJS answers.
 const (
 	answering               = iota
@@ -552,6 +587,17 @@ func wantAsked(t *testing.T, geojs *standIn, i int, want ...string) {
 	}
 }
 
+// wantUnanswered checks how many requests m counts as having gone without
+// an answer from GeoJS.
+func wantUnanswered(t *testing.T, m *metrics.Metrics, want float64) {
+	t.Helper()
+
+	got := testutil.ToFloat64(m.GeoJSUnanswered)
+	if got != want {
+		t.Errorf("%v requests went without an answer, want %v", got, want)
+	}
+}
+
 // waitForRequests waits until g has done all it can before time passes,
 // checks that GeoJS has had count requests, and returns the addresses each
 // asked about.

internal/proxy/admin.go

@@ -10,8 +10,9 @@ import (
 
 // answerAdmin answers a request for smallwebwaf itself, under
 // /_smallwebwaf/, once it has passed the checks: GET MetricsPath with
-// SWWAF_METRICS_TOKEN gets the metrics, and without it 401. Any other
+// SWWAF_METRICS_TOKEN gets the metrics, and without it is refused with
-// request gets 404, as the metrics do while SWWAF_METRICS_TOKEN is unset.
+// 401. Any other request gets 404, as the metrics do while
+// SWWAF_METRICS_TOKEN is unset.
 func (rq *request) answerAdmin() {
 	rq.line.Action = requestlog.ActionAdmin
 	rq.startClientResponseTimeout()
@@ -23,8 +24,10 @@ func (rq *request) answerAdmin() {
 		http.Error(rq.out, http.StatusText(http.StatusNotFound), http.StatusNotFound)
 	case !hasToken(rq.in, token):
 		rq.out.Header().Set("WWW-Authenticate", "Bearer")
-		http.Error(rq.out, http.StatusText(http.StatusUnauthorized),
+		rq.answer(refusal{
-			http.StatusUnauthorized)
+			status: http.StatusUnauthorized,
+			action: requestlog.ActionAdmin,
+		})
 	default:
 		rq.h.metrics.ServeHTTP(rq.out, rq.in)
 	}

internal/proxy/history_test.go

@@ -86,21 +86,24 @@ func TestHealthEndpointIsNotInTheHistory(t *testing.T) {
 	}
 }
 
-func TestRequestForSmallwebwafIsNeitherForwardedNorRefused(t *testing.T) {
+func TestRequestForSmallwebwafIsRefusedOnlyWithoutTheToken(t *testing.T) {
 	t.Parallel()
 
 	app := startApp(t, func(http.ResponseWriter, *http.Request) {})
 	addr, out, server := startProxyWithClock(t, app.URL, "", time.Now,
 		map[string]string{metricsToken: token})
 
+	// The metrics and the 404 are neither forwarded nor refused; the 401
+	// is refused.
 	scrape(t, addr)
 	wantStatus(t, get(t, addr, "/_smallwebwaf/nothing"), http.StatusNotFound)
-	out.requestLines(t, 2)
+	wantStatus(t, get(t, addr, proxy.MetricsPath), http.StatusUnauthorized)
+	out.requestLines(t, 3)
 
 	history := historyOf(t, server, localhost)
-	if history.Requests != 2 || history.Forwarded != 0 || history.Refused != 0 {
+	if history.Requests != 3 || history.Forwarded != 0 || history.Refused != 1 {
 		t.Errorf("history counts %d requests, %d forwarded and %d refused, "+
-			"want 2, 0 and 0", history.Requests, history.Forwarded, history.Refused)
+			"want 3, 0 and 1", history.Requests, history.Forwarded, history.Refused)
 	}
 }
 

internal/proxy/limits_test.go

@@ -55,6 +55,7 @@ func TestRequestBodyLimit(t *testing.T) {
 			})
 			addr, out := startProxy(t, app.URL, map[string]string{
 				requestMaxBytes: sizeLimitSetting,
+				metricsToken:    token,
 			})
 
 			var body io.Reader = bytes.NewReader(make([]byte, tc.size))
@@ -66,6 +67,13 @@ func TestRequestBodyLimit(t *testing.T) {
 				tc.want)
 			wantLine(t, out.requestLine(t), tc.want, tc.action)
 
+			hits := 0
+			if tc.action == requestlog.ActionTooLarge {
+				hits = 1
+			}
+
+			wantLimitHits(t, addr, requestMaxBytes, hits)
+
 			if tc.refusedBeforeApp && calls.Load() != 0 {
 				t.Errorf("the app was called %d times, want never", calls.Load())
 			}
@@ -106,6 +114,7 @@ func TestResponseBodyLimit(t *testing.T) {
 			})
 			addr, out := startProxy(t, app.URL, map[string]string{
 				responseMaxBytes: sizeLimitSetting,
+				metricsToken:     token,
 			})
 
 			got := get(t, addr, "/download")
@@ -123,6 +132,13 @@ func TestResponseBodyLimit(t *testing.T) {
 			if line.UpstreamStatus != http.StatusOK {
 				t.Errorf("log line has upstream_status %d", line.UpstreamStatus)
 			}
+
+			hits := 0
+			if tc.action == requestlog.ActionTooLarge {
+				hits = 1
+			}
+
+			wantLimitHits(t, addr, responseMaxBytes, hits)
 		})
 	}
 }

internal/proxy/metrics_test.go

@@ -1,7 +1,6 @@
 package proxy_test
 
 import (
-	"bytes"
 	"io"
 	"net/http"
 	"net/http/httptest"
@@ -244,34 +243,6 @@ func TestMetricsCountLimitsAndBans(t *testing.T) {
 	wantMetric(t, metrics, "smallwebwaf_tracked_clients", 3)
 }
 
-func TestMetricsCountSizeAndTimeLimits(t *testing.T) {
-	t.Parallel()
-
-	// The app never answers /hang, so the timeout runs out however slowly
-	// the test runs.
-	app := startApp(t, func(_ http.ResponseWriter, r *http.Request) {
-		if r.URL.Path == "/hang" {
-			<-r.Context().Done()
-		}
-	})
-	addr, out := startProxy(t, app.URL, map[string]string{
-		metricsToken:            token,
-		requestMaxBytes:         sizeLimitSetting,
-		upstreamResponseTimeout: "100ms",
-	})
-
-	body := bytes.NewReader(make([]byte, 2*sizeLimit))
-	wantStatus(t, do(t, newRequest(t, http.MethodPost, addr, "/", body)),
-		http.StatusRequestEntityTooLarge)
-	wantStatus(t, get(t, addr, "/hang"), http.StatusGatewayTimeout)
-	out.requestLines(t, 2)
-
-	metrics := scrape(t, addr)
-	hits := "smallwebwaf_size_and_time_limit_hits_total"
-	wantMetric(t, metrics, hits+`{limit="SWWAF_REQUEST_MAX_BYTES"}`, 1)
-	wantMetric(t, metrics, hits+`{limit="SWWAF_UPSTREAM_RESPONSE_TIMEOUT"}`, 1)
-}
-
 func TestMetricsByCountryKeepTheBusiestAndCountTheRestAsOther(t *testing.T) {
 	t.Parallel()
 
@@ -464,3 +435,21 @@ func wantNoSeries(t *testing.T, metrics, series string) {
 		t.Errorf("there is a series %s", series)
 	}
 }
+
+// wantLimitHits checks that the metrics of smallwebwaf at addr count hits
+// requests that passed the size or time limit of the setting limit, with
+// no series for it when hits is 0.
+func wantLimitHits(t *testing.T, addr, limit string, hits int) {
+	t.Helper()
+
+	series := `smallwebwaf_size_and_time_limit_hits_total{limit="` + limit + `"}`
+	metrics := scrape(t, addr)
+
+	if hits == 0 {
+		wantNoSeries(t, metrics, series)
+
+		return
+	}
+
+	wantMetric(t, metrics, series, float64(hits))
+}

internal/proxy/timeouts_test.go

@@ -28,7 +28,9 @@ func TestRequestTimeouts(t *testing.T) {
 
 	for _, tc := range []struct {
 		name string
-		env  map[string]string
+		// limit is the setting set to shortTimeout, which runs out; long
+		// is one set to longTimeoutSetting, which does not, or "".
+		limit, long string
 		// appTakesNothing has the app never read, while the client sends
 		// as fast as it can; otherwise the app reads, and the client
 		// stops sending halfway.
@@ -36,30 +38,26 @@ func TestRequestTimeouts(t *testing.T) {
 		want            int
 	}{
 		{
-			name: "client request timeout, waiting on the client",
+			name:  "client request timeout, waiting on the client",
-			env:  map[string]string{clientRequestTimeout: shortTimeoutSetting},
+			limit: clientRequestTimeout,
-			want: http.StatusRequestTimeout,
+			want:  http.StatusRequestTimeout,
 		},
 		{
-			name: "upstream request timeout, waiting on the client",
+			name:  "upstream request timeout, waiting on the client",
-			env: map[string]string{
+			limit: upstreamRequestTimeout,
-				upstreamRequestTimeout: shortTimeoutSetting,
+			long:  clientRequestTimeout,
-				clientRequestTimeout:   longTimeoutSetting,
+			want:  http.StatusRequestTimeout,
-			},
-			want: http.StatusRequestTimeout,
 		},
 		{
 			name:            "upstream request timeout, waiting on the app",
-			env:             map[string]string{upstreamRequestTimeout: shortTimeoutSetting},
+			limit:           upstreamRequestTimeout,
 			appTakesNothing: true,
 			want:            http.StatusGatewayTimeout,
 		},
 		{
-			name: "client request timeout, waiting on the app",
+			name:            "client request timeout, waiting on the app",
-			env: map[string]string{
+			limit:           clientRequestTimeout,
-				clientRequestTimeout:   shortTimeoutSetting,
+			long:            upstreamRequestTimeout,
-				upstreamRequestTimeout: longTimeoutSetting,
-			},
 			appTakesNothing: true,
 			want:            http.StatusGatewayTimeout,
 		},
@@ -84,7 +82,12 @@ func TestRequestTimeouts(t *testing.T) {
 				appURL, sendRequest = app.URL, sendPartOfBody
 			}
 
-			addr, out := startProxy(t, appURL, tc.env)
+			env := map[string]string{tc.limit: shortTimeoutSetting, metricsToken: token}
+			if tc.long != "" {
+				env[tc.long] = longTimeoutSetting
+			}
+
+			addr, out := startProxy(t, appURL, env)
 			start := time.Now()
 			got := readResponse(t, sendRequest(t, addr))
 			wantTimedOut(t, start)
@@ -105,6 +108,7 @@ func TestRequestTimeouts(t *testing.T) {
 
 			wantStatus(t, got, want)
 			wantLine(t, out.requestLine(t), want, requestlog.ActionTimedOut)
+			wantLimitHits(t, addr, tc.limit, 1)
 		})
 	}
 }
@@ -198,6 +202,7 @@ func TestAppTooSlowToAnswer(t *testing.T) {
 	})
 	addr, out := startProxy(t, app.URL, map[string]string{
 		upstreamResponseTimeout: shortTimeoutSetting,
+		metricsToken:            token,
 	})
 
 	start := time.Now()
@@ -213,6 +218,8 @@ func TestAppTooSlowToAnswer(t *testing.T) {
 		t.Errorf("log line has upstream_status %v for an app that never answered",
 			line.fields["upstream_status"])
 	}
+
+	wantLimitHits(t, addr, upstreamResponseTimeout, 1)
 }
 
 func TestAppTooSlowToFinishItsAnswer(t *testing.T) {
@@ -261,6 +268,7 @@ func TestClientTooSlowToTakeTheAnswer(t *testing.T) {
 	})
 	addr, out := startProxy(t, app.URL, map[string]string{
 		clientResponseTimeout: shortTimeoutSetting,
+		metricsToken:          token,
 	})
 
 	start := time.Now()
@@ -272,6 +280,7 @@ func TestClientTooSlowToTakeTheAnswer(t *testing.T) {
 	line := out.requestLine(t)
 	wantTimedOut(t, start)
 	wantLine(t, line, http.StatusOK, requestlog.ActionTimedOut)
+	wantLimitHits(t, addr, clientResponseTimeout, 1)
 }
 
 func TestClosesAnIdleConnection(t *testing.T) {

internal/ratelimit/history_test.go

@@ -23,8 +23,8 @@ func TestHistoryKeepsEveryRequest(t *testing.T) {
 		{Forwarded: true, Status: 502, ResponseBytes: 12},
 		// Closed without an answer: refused, and no response.
 		{Refused: true, Status: 0},
-		// Answered at smallwebwaf's own endpoints: neither forwarded nor
+		// Answered 404 at smallwebwaf's own endpoints: neither forwarded
-		// refused.
+		// nor refused.
 		{Status: 404},
 	} {
 		limiter.AddToHistory(client, start.Add(time.Duration(i)*time.Minute), r)

internal/ratelimit/ratelimit.go

@@ -71,8 +71,9 @@ type History struct {
 	Country  string    `json:"country,omitempty"`
 	LookedUp time.Time `json:"looked_up,omitzero"`
 	// Requests are all the client's requests: Forwarded those passed to
-	// the app, Refused those refused before anything reached it, and
+	// the app, Refused those refused before anything reached it, a 401 at
-	// neither those smallwebwaf answered at its own endpoints.
+	// smallwebwaf's own endpoints included, and neither the others
+	// smallwebwaf answered there.
 	Requests  int64 `json:"requests"`
 	Forwarded int64 `json:"forwarded"`
 	Refused   int64 `json:"refused"`
@@ -105,8 +106,9 @@ type Request struct {
 	// Country is the client's country, when the request looked it up.
 	Country string
 	// Forwarded is true for a request passed to the app, Refused for one
-	// refused before anything reached it. Both are false for a request
+	// refused before anything reached it, a 401 at smallwebwaf's own
-	// smallwebwaf answered at its own endpoints.
+	// endpoints included. Both are false for any other request smallwebwaf
+	// answered there.
 	Forwarded bool
 	Refused   bool
 	// Status is what the client was sent, 0 if nothing was.