servewaf: each decision heuristic is its own module (closes #195)

Each check servewaf runs on a request is a type in its own file behind
one interface, heuristic, and is registered in one of four ordered lists
in heuristics.go. Order and behaviour are unchanged.

Every refusal now logs heuristic, the name of the heuristic that made
it, and heuristic_figures, the figures it acted on. A ban by
refusal_limit or byte_limits after the answer logs after_answer_heuristic
and after_answer_heuristic_figures instead, so a line can name both. All
four are in docs/request-log.md, and SPEC.md names each heuristic at its
step.

Model: opus-5-5

SPEC.md

@@ -123,8 +123,9 @@ runs steps 3 to 13, and does the counting of step 15. The first step that
 produces a final answer ends the checks. Step 15 runs for each request
 `servewaf` answers with `allow`, `deny` or `close`. `rproxy`'s size and time
 limits apply to the whole exchange. Each step names the section that holds its
-rules. Each check is a heuristic, whose name the request log's `heuristic` field
-gives, shown here in parentheses.
+rules. Each check is a heuristic. Its name, in parentheses below, is the value
+of the request log's `heuristic` field. `refusal_limit` and `byte_limits` give
+theirs in `after_answer_heuristic` instead.
 
 1. `GET /_smallwebwaf/healthz` is answered at once by `rproxy`, before any
    check, so a health checker never needs an exemption and is never refused.

docs/request-log.md

@@ -107,8 +107,8 @@ Every one of these lines has:
 - `would_action`: in `observe` mode, what `enforce` mode would have done with a
   request it would have refused. `action` then names what was done, normally
   `forward`.
-- `heuristic`: the heuristic that refused the request or banned its client, in
-  `observe` mode too. It is left out when none did.
+- `heuristic`: the heuristic that refused the request, in `observe` mode too. It
+  is left out when none did.
 - `heuristic_figures`: an object of the figures that heuristic acted on. Each
   heuristic and its figures:
     - `deny_nets`: `netblock`, the entry of `SWWAF_DENY_NETS` the client is in;
@@ -127,10 +127,14 @@ Every one of these lines has:
     - `core_rule_set`: `score`, and `threshold`, `SWWAF_WAF_ANOMALY_THRESHOLD`;
     - `refusal_limit`: `window`, `count` and `limit`, of the error burst;
     - `byte_limits`: `window`, `count` and `limit`, the count in bytes.
+- `after_answer_heuristic`: the heuristic that banned the client after
+  `servewaf` answered the request, in `observe` mode too: `refusal_limit` or
+  `byte_limits`.
+- `after_answer_heuristic_figures`: an object of the figures that heuristic
+  acted on, as listed above.
 
-    `refusal_limit` bans after a request refused by another heuristic has been
-    answered, so it replaces that heuristic on the line. `byte_limits` bans when
-    the report comes, so only the `report` line names it.
+    `byte_limits` bans when the report comes, so only the `report` line names
+    it.
 
 - `limit_percent` and `limit_percent_setting`: the client's percentage of the
   rate limits and the setting that lowered it, when one did. `bytes_percent` and

internal/requestlog/requestlog.go

@@ -131,11 +131,16 @@ type Line struct {
 	// ActionRuleBlocked, ActionWAFBlocked, or, in servewaf, ActionTooLarge
 	// for the header limits.
 	WouldAction string `json:"would_action,omitempty"`
-	// Heuristic is the name of the heuristic that refused the request or
-	// banned its client, in observe mode too, and HeuristicFigures are the
-	// figures it acted on, by name.
+	// Heuristic is the name of the heuristic that refused the request, in
+	// observe mode too, and HeuristicFigures are the figures it acted on, by
+	// name.
 	Heuristic        string         `json:"heuristic,omitempty"`
 	HeuristicFigures map[string]any `json:"heuristic_figures,omitempty"`
+	// AfterAnswerHeuristic and AfterAnswerHeuristicFigures are the same for
+	// the heuristic that banned the client after servewaf answered the
+	// request.
+	AfterAnswerHeuristic        string         `json:"after_answer_heuristic,omitempty"`
+	AfterAnswerHeuristicFigures map[string]any `json:"after_answer_heuristic_figures,omitempty"` //nolint:lll // a struct tag cannot be split
 	// LimitPercent and LimitPercentSetting are, for a request the rate
 	// limits counted whose client a biased threshold gives a percentage of
 	// the rate limits below 100, that percentage and the setting that gave

internal/servewaf/bans.go

@@ -52,7 +52,7 @@ func (activeBan) check(_ context.Context, rq *request, now time.Time) *verdict {
 	return &verdict{
 		action: requestlog.ActionBanned,
 		figures: map[string]any{
-			"netblock": ban.Netblock.String(), "ban_expires": rq.line.BanExpires,
+			figureNetblock: ban.Netblock.String(), "ban_expires": rq.line.BanExpires,
 		},
 	}
 }
@@ -60,7 +60,9 @@ func (activeBan) check(_ context.Context, rq *request, now time.Time) *verdict {
 // limitFigures are the figures of a heuristic that broke hit, a limit: its
 // window, the count and the limit.
 func limitFigures(hit ratelimit.Hit) map[string]any {
-	return map[string]any{"window": hit.Window, "count": hit.Count, figureLimit: hit.Limit}
+	return map[string]any{
+		figureWindow: hit.Window, figureCount: hit.Count, figureLimit: hit.Limit,
+	}
 }
 
 // countedBytes returns the request's bytes, once it has ended, as the

internal/servewaf/blocklists.go

@@ -23,7 +23,7 @@ func (blocklists) check(_ context.Context, rq *request, _ time.Time) *verdict {
 	rq.blocklisted = len(listedBy) > 0
 	rq.noteListed(listedBy, "listed by a blocklist")
 
-	if !rq.blocklisted || rq.h.config.BlocklistAction != deny {
+	if !rq.refusedByBlocklists(listedBy) {
 		return nil
 	}
 
@@ -32,3 +32,10 @@ func (blocklists) check(_ context.Context, rq *request, _ time.Time) *verdict {
 		figures: map[string]any{"lists": listedBy},
 	}
 }
+
+// refusedByBlocklists reports whether the heuristic blocklists refuses a
+// client, given listedBy, the blocklists that list it: it does when one lists
+// it and SWWAF_BLOCKLIST_ACTION is deny.
+func (rq *request) refusedByBlocklists(listedBy []string) bool {
+	return len(listedBy) > 0 && rq.h.config.BlocklistAction == deny
+}

internal/servewaf/bytelimits_test.go

@@ -104,11 +104,12 @@ func TestByteLimitBanNamesItsHeuristicWindowCountAndLimit(t *testing.T) {
 	s, _ := startWithAnswers(t, map[string]string{bytesLimitPerMinute: byteLimit})
 
 	line, _ := s.download()
-	wantHeuristic(t, line, "", "null")
+	wantAfterAnswerHeuristic(t, line, "", "null")
 
 	// Two answers of 70 bytes are over the limit of 99.
 	line, _ = s.download()
-	wantHeuristic(t, line, "byte_limits",
+	wantHeuristic(t, line, "", "null")
+	wantAfterAnswerHeuristic(t, line, "byte_limits",
 		`{"window": "minute", "count": 140, "limit": 99}`)
 }
 

internal/servewaf/crowdsec.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"sneak.berlin/go/smallwebwaf/internal/bans"
+	"sneak.berlin/go/smallwebwaf/internal/reputation"
 	"sneak.berlin/go/smallwebwaf/internal/requestlog"
 )
 
@@ -20,7 +21,7 @@ type crowdSec struct{}
 func (crowdSec) name() string { return "crowdsec" }
 
 func (crowdSec) check(_ context.Context, rq *request, now time.Time) *verdict {
-	decision, listed := rq.h.lists.CrowdSecDecision(rq.client, now)
+	decision, listed := rq.crowdSecDecisionInForce(now)
 	if !listed {
 		return nil
 	}
@@ -37,3 +38,12 @@ func (crowdSec) check(_ context.Context, rq *request, now time.Time) *verdict {
 		},
 	}
 }
+
+// crowdSecDecisionInForce returns the decision of the CrowdSec decision list on
+// the client that is in force at now, and reports whether there is one, which
+// the heuristic crowdsec refuses the request for.
+func (rq *request) crowdSecDecisionInForce(
+	now time.Time,
+) (reputation.Decision, bool) {
+	return rq.h.lists.CrowdSecDecision(rq.client, now)
+}

internal/servewaf/denynets.go

@@ -20,7 +20,7 @@ func (denyNets) check(_ context.Context, rq *request, _ time.Time) *verdict {
 		if netblock.Contains(rq.client) {
 			return &verdict{
 				action:  requestlog.ActionDenied,
-				figures: map[string]any{"netblock": netblock.String()},
+				figures: map[string]any{figureNetblock: netblock.String()},
 			}
 		}
 	}

internal/servewaf/headerlimits.go

@@ -25,7 +25,7 @@ func (headerLimits) name() string { return "header_limits" }
 
 func (headerLimits) check(_ context.Context, rq *request, _ time.Time) *verdict {
 	fields, cookies := rq.headerCounts()
-	if fields <= maxHeaderFields && cookies <= maxCookies {
+	if !overHeaderLimits(fields, cookies) {
 		return nil
 	}
 
@@ -38,12 +38,10 @@ func (headerLimits) check(_ context.Context, rq *request, _ time.Time) *verdict
 	}
 }
 
-// overHeaderLimits reports whether the request is over the header limits: it
-// has more than maxHeaderFields fields or more than maxCookies cookies, as
-// headerCounts counts them.
-func (rq *request) overHeaderLimits() bool {
-	fields, cookies := rq.headerCounts()
-
+// overHeaderLimits reports whether a request with these counts of header fields
+// and cookies, as headerCounts counts them, is over the header limits: it has
+// more than maxHeaderFields fields or more than maxCookies cookies.
+func overHeaderLimits(fields, cookies int) bool {
 	return fields > maxHeaderFields || cookies > maxCookies
 }
 

internal/servewaf/heuristics.go

@@ -28,8 +28,11 @@ type verdict struct {
 
 // The names of the figures that more than one heuristic gives.
 const (
-	figureLimit = "limit"
-	figureScore = "score"
+	figureWindow   = "window"
+	figureCount    = "count"
+	figureLimit    = "limit"
+	figureScore    = "score"
+	figureNetblock = "netblock"
 )
 
 // The lists of heuristics, each in the order its heuristics run. A client in
@@ -81,24 +84,50 @@ func onReport() []heuristic {
 // runAfterAnswer runs the heuristics of afterAnswer on the request, at the time
 // it is called.
 func (rq *request) runAfterAnswer(ctx context.Context) {
-	rq.runHeuristics(ctx, afterAnswer(), rq.h.now())
+	rq.runBanningHeuristics(ctx, afterAnswer())
 }
 
-// runHeuristics runs list on the request at now, in order, and returns the
-// first verdict, or nil when none gives one. The log line names the heuristic
-// that gave it, and its figures. ctx is the request's own context.
+// runHeuristics runs list, beforeLookup or afterLookup, on the request at now,
+// and returns the first verdict, or nil when none gives one. The log line's
+// heuristic and heuristic_figures name the heuristic that gave it, and give its
+// figures. ctx is the request's own context.
 func (rq *request) runHeuristics(
 	ctx context.Context, list []heuristic, now time.Time,
 ) *verdict {
+	name, v := rq.firstVerdict(ctx, list, now)
+	if v != nil {
+		rq.line.Heuristic = name
+		rq.line.HeuristicFigures = v.figures
+	}
+
+	return v
+}
+
+// runBanningHeuristics runs list, afterAnswer or onReport, on the request at
+// the time it is called. The log line's after_answer_heuristic and
+// after_answer_heuristic_figures name the heuristic that gave a verdict, and
+// give its figures, so that heuristic and heuristic_figures still name the one
+// that refused the request. ctx is the request's own context.
+func (rq *request) runBanningHeuristics(ctx context.Context, list []heuristic) {
+	name, v := rq.firstVerdict(ctx, list, rq.h.now())
+	if v != nil {
+		rq.line.AfterAnswerHeuristic = name
+		rq.line.AfterAnswerHeuristicFigures = v.figures
+	}
+}
+
+// firstVerdict runs list on the request at now, in order, until a heuristic
+// gives a verdict, and returns that heuristic's name and its verdict, or "" and
+// nil when none gives one. ctx is the request's own context.
+func (rq *request) firstVerdict(
+	ctx context.Context, list []heuristic, now time.Time,
+) (string, *verdict) {
 	for _, each := range list {
 		v := each.check(ctx, rq, now)
 		if v != nil {
-			rq.line.Heuristic = each.name()
-			rq.line.HeuristicFigures = v.figures
-
-			return v
+			return each.name(), v
 		}
 	}
 
-	return nil
+	return "", nil
 }

internal/servewaf/ratelimits.go

@@ -45,6 +45,15 @@ func (rateLimits) check(_ context.Context, rq *request, now time.Time) *verdict
 	return &verdict{action: requestlog.ActionRateLimited, figures: limitFigures(hit)}
 }
 
+// overAWholeRateLimit reports whether the heuristic rate_limits will refuse the
+// request at now, whatever its client's limit percentages: the rate limits
+// count it, and one more request from its client takes it over a whole rate
+// limit. It counts nothing.
+func (rq *request) overAWholeRateLimit(now time.Time) bool {
+	return rq.countedByRateLimits() &&
+		rq.h.limiter.OverARateLimit(rq.h.clientGroup(rq.client), now)
+}
+
 // countedByRateLimits reports whether the rate limits count the request: its
 // client is not in SWWAF_RATE_LIMIT_EXEMPT_NETS, and its path is not exempt
 // under SWWAF_RATE_LIMIT_EXEMPT_PATHS.

internal/servewaf/refusallimit_test.go

@@ -111,13 +111,18 @@ func TestRefusalLimitBanNamesItsHeuristicWindowCountAndLimit(t *testing.T) {
 
 	s, _, _ := startForErrorBurst(t, "1", nil)
 
+	const ruleFigures = `{"rule_id": "blocked", "rule_action": "block"}`
+
 	line := blockRule.send(s, client)
-	wantHeuristic(t, line, "rule_files", `{"rule_id": "blocked", "rule_action": "block"}`)
+	wantHeuristic(t, line, "rule_files", ruleFigures)
+	wantAfterAnswerHeuristic(t, line, "", "null")
 
 	// The second refusal is the request refusal_limit bans for, and the line
-	// names it instead of rule_files.
+	// names both.
 	line = blockRule.send(s, client)
-	wantHeuristic(t, line, "refusal_limit", `{"window": "minute", "count": 2, "limit": 1}`)
+	wantHeuristic(t, line, "rule_files", ruleFigures)
+	wantAfterAnswerHeuristic(t, line, "refusal_limit",
+		`{"window": "minute", "count": 2, "limit": 1}`)
 }
 
 func TestErrorBurstBanNotesHistoryAndMetrics(t *testing.T) {

internal/servewaf/requestlog_test.go

@@ -274,22 +274,45 @@ func wantTimings(t *testing.T, line logLine, want ...string) {
 }
 
 // wantHeuristic checks that line names heuristic as the one that refused the
-// request or banned its client, with figures, a JSON object. A heuristic of ""
-// with figures "null" is a line that names none.
+// request, with figures, a JSON object. A heuristic of "" with figures "null" is
+// a line that names none.
 func wantHeuristic(t *testing.T, line logLine, heuristic, figures string) {
 	t.Helper()
 
-	var want map[string]any
+	if line.Heuristic != heuristic ||
+		!reflect.DeepEqual(line.HeuristicFigures, decodeFigures(t, figures)) {
+		t.Errorf("log line has heuristic %q with heuristic_figures %v, want %q with %s",
+			line.Heuristic, line.HeuristicFigures, heuristic, figures)
+	}
+}
 
-	err := json.Unmarshal([]byte(figures), &want)
+// wantAfterAnswerHeuristic checks after_answer_heuristic and
+// after_answer_heuristic_figures as wantHeuristic checks heuristic and
+// heuristic_figures.
+func wantAfterAnswerHeuristic(t *testing.T, line logLine, heuristic, figures string) {
+	t.Helper()
+
+	if line.AfterAnswerHeuristic != heuristic ||
+		!reflect.DeepEqual(line.AfterAnswerHeuristicFigures, decodeFigures(t, figures)) {
+		t.Errorf("log line has after_answer_heuristic %q with "+
+			"after_answer_heuristic_figures %v, want %q with %s",
+			line.AfterAnswerHeuristic, line.AfterAnswerHeuristicFigures, heuristic, figures)
+	}
+}
+
+// decodeFigures decodes figures, a JSON object of a heuristic's figures, as
+// the log line's figures are decoded.
+func decodeFigures(t *testing.T, figures string) map[string]any {
+	t.Helper()
+
+	var decoded map[string]any
+
+	err := json.Unmarshal([]byte(figures), &decoded)
 	if err != nil {
 		t.Fatalf("decode %s: %v", figures, err)
 	}
 
-	if line.Heuristic != heuristic || !reflect.DeepEqual(line.HeuristicFigures, want) {
-		t.Errorf("log line has heuristic %q with heuristic_figures %v, want %q with %s",
-			line.Heuristic, line.HeuristicFigures, heuristic, figures)
-	}
+	return decoded
 }
 
 // microseconds is a timing in whole microseconds.

internal/servewaf/servewaf.go

@@ -141,22 +141,20 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 // refusedWhateverTheAnswer reports whether the request is one that does not wait
 // for GeoJS, since the checks will refuse it at now whatever GeoJS answers about
-// its client: it is over the header limits, a blocklist lists its client while
-// SWWAF_BLOCKLIST_ACTION is deny, the CrowdSec decision list lists it, or it is
-// over a whole rate limit. In observe mode, which refuses nothing, none is.
-// rproxy lets a request through when servewaf answers too late.
+// its client: the heuristic crowdsec, header_limits, blocklists or rate_limits
+// will refuse it, as a function in that heuristic's file says. In observe mode,
+// which refuses nothing, none is. rproxy lets a request through when servewaf
+// answers too late.
 func (rq *request) refusedWhateverTheAnswer(now time.Time) bool {
 	if rq.h.config.Observe {
 		return false
 	}
 
-	lists := rq.h.lists
-	_, decided := lists.CrowdSecDecision(rq.client, now)
+	_, decided := rq.crowdSecDecisionInForce(now)
 
-	return decided || rq.overHeaderLimits() ||
-		(rq.h.config.BlocklistAction == deny && len(lists.ListedBy(rq.client)) > 0) ||
-		(rq.countedByRateLimits() &&
-			rq.h.limiter.OverARateLimit(rq.h.clientGroup(rq.client), now))
+	return decided || overHeaderLimits(rq.headerCounts()) ||
+		rq.refusedByBlocklists(rq.h.lists.ListedBy(rq.client)) ||
+		rq.overAWholeRateLimit(now)
 }
 
 // answerQuestion runs the checks on the visitor's request a question
@@ -464,7 +462,7 @@ func (h *handler) finishWith(ctx context.Context, held *decision, report Report)
 	if rq.allowed {
 		rq.line.DurationUpstreamTotal = &report.DurationUpstreamTotal
 
-		rq.runHeuristics(ctx, onReport(), rq.h.now())
+		rq.runBanningHeuristics(ctx, onReport())
 		rq.countAnomalies()
 		rq.addToHistory()