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
+rules. Each check is a heuristic. Its name, in parentheses below, is the value
-gives, shown here in parentheses.
+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
+- `heuristic`: the heuristic that refused the request, in `observe` mode too. It
-  `observe` mode too. It is left out when none did.
+  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
+    `byte_limits` bans when the report comes, so only the `report` line names
-    answered, so it replaces that heuristic on the line. `byte_limits` bans when
+    it.
-    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
+	// Heuristic is the name of the heuristic that refused the request, in
-	// banned its client, in observe mode too, and HeuristicFigures are the
+	// observe mode too, and HeuristicFigures are the figures it acted on, by
-	// figures it acted on, by name.
+	// 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
+// overHeaderLimits reports whether a request with these counts of header fields
-// has more than maxHeaderFields fields or more than maxCookies cookies, as
+// and cookies, as headerCounts counts them, is over the header limits: it has
-// headerCounts counts them.
+// more than maxHeaderFields fields or more than maxCookies cookies.
-func (rq *request) overHeaderLimits() bool {
+func overHeaderLimits(fields, cookies int) bool {
-	fields, cookies := rq.headerCounts()
-
 	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"
+	figureWindow   = "window"
-	figureScore = "score"
+	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
+// runHeuristics runs list, beforeLookup or afterLookup, on the request at now,
-// first verdict, or nil when none gives one. The log line names the heuristic
+// and returns the first verdict, or nil when none gives one. The log line's
-// that gave it, and its figures. ctx is the request's own context.
+// 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()
+			return each.name(), v
-			rq.line.HeuristicFigures = v.figures
-
-			return 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 ""
+// request, with figures, a JSON object. A heuristic of "" with figures "null" is
-// with figures "null" is a line that names none.
+// 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) {
+	return decoded
-		t.Errorf("log line has heuristic %q with heuristic_figures %v, want %q with %s",
-			line.Heuristic, line.HeuristicFigures, heuristic, figures)
-	}
 }
 
 // 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
+// its client: the heuristic crowdsec, header_limits, blocklists or rate_limits
-// SWWAF_BLOCKLIST_ACTION is deny, the CrowdSec decision list lists it, or it is
+// will refuse it, as a function in that heuristic's file says. In observe mode,
-// over a whole rate limit. In observe mode, which refuses nothing, none is.
+// which refuses nothing, none is. rproxy lets a request through when servewaf
-// rproxy lets a request through when servewaf answers too late.
+// answers too late.
 func (rq *request) refusedWhateverTheAnswer(now time.Time) bool {
 	if rq.h.config.Observe {
 		return false
 	}
 
-	lists := rq.h.lists
+	_, decided := rq.crowdSecDecisionInForce(now)
-	_, decided := lists.CrowdSecDecision(rq.client, now)
 
-	return decided || rq.overHeaderLimits() ||
+	return decided || overHeaderLimits(rq.headerCounts()) ||
-		(rq.h.config.BlocklistAction == deny && len(lists.ListedBy(rq.client)) > 0) ||
+		rq.refusedByBlocklists(rq.h.lists.ListedBy(rq.client)) ||
-		(rq.countedByRateLimits() &&
+		rq.overAWholeRateLimit(now)
-			rq.h.limiter.OverARateLimit(rq.h.clientGroup(rq.client), 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()