Observe mode: log what would be refused, refuse nothing (closes #78)

SWWAF_MODE (default enforce) takes enforce or observe. In observe mode a
request that SWWAF_DENY_NETS, a ban, the country lists or a rate limit
would refuse is passed to the app, and its log line names that refusal
in would_action. The size and time limits and the 401 still apply. A
broken limit makes no ban; bans read from bans.json are kept but refuse
nothing, and Ledger.Find reads them without counting a refusal in their
notes.

Judgement call: in observe mode a broken limit does not reset the
client's counters, since the reset comes with the ban.
Judgement call: a request a ban would refuse keeps ban_expires.

Model: opus-5-5

internal/proxy/bans.go

@@ -14,10 +14,15 @@ func (rq *request) banResponse(action string) *refusal {
 	return &refusal{status: rq.h.config.BanResponse, action: action}
 }
 
-// banned reports whether a ban on a netblock the client is in refuses
-// the request at now, and notes for the log line when that ban ends.
+// banned reports whether a ban on a netblock the client is in covers the
+// request at now, and notes for the log line when that ban ends.
 func (rq *request) banned(now time.Time) bool {
-	ban, banned := rq.h.ledger.Check(rq.client, now)
+	check := rq.h.ledger.Check
+	if rq.h.config.Observe {
+		check = rq.h.ledger.Find // in observe mode the ban refuses nothing
+	}
+
+	ban, banned := check(rq.client, now)
 	if banned {
 		rq.line.BanExpires = banExpires(ban)
 	}
@@ -26,8 +31,9 @@ func (rq *request) banned(now time.Time) bool {
 }
 
 // limitBroken counts the request for the rate limits at now, and reports
-// whether it takes the client over one. Such a request bans the client's
-// netblock, and sets the client's counters back to zero.
+// whether it takes the client over one. In enforce mode such a request
+// bans the client's netblock, and sets the client's counters back to
+// zero; in observe mode it does neither.
 func (rq *request) limitBroken(now time.Time) bool {
 	group := clientGroup(rq.client)
 
@@ -36,6 +42,13 @@ func (rq *request) limitBroken(now time.Time) bool {
 		return false
 	}
 
+	rq.line.LimitHit = hit.Window
+	rq.line.Offence = requestlog.OffenceLimit
+
+	if rq.h.config.Observe {
+		return true
+	}
+
 	netblock := rq.netblock()
 	ban := rq.h.ledger.BanForLimit(netblock, now, bans.Notes{
 		Country: rq.line.Country,
@@ -54,9 +67,6 @@ func (rq *request) limitBroken(now time.Time) bool {
 		Requests: rq.h.limiter.Requests(netblock) + 1,
 	})
 	rq.h.limiter.Reset(group)
-
-	rq.line.LimitHit = hit.Window
-	rq.line.Offence = requestlog.OffenceLimit
 	rq.line.BanExpires = banExpires(ban)
 
 	return true

internal/proxy/observe_test.go

@@ -0,0 +1,202 @@
+package proxy_test
+
+import (
+	"bytes"
+	"io"
+	"net/http"
+	"net/netip"
+	"sync/atomic"
+	"testing"
+	"time"
+
+	"sneak.berlin/go/smallwebwaf/internal/bans"
+	"sneak.berlin/go/smallwebwaf/internal/proxy"
+	"sneak.berlin/go/smallwebwaf/internal/requestlog"
+)
+
+// observe is the value of SWWAF_MODE for observe mode.
+const observe = "observe"
+
+func TestObserveModeForwardsWhatEnforceModeRefuses(t *testing.T) {
+	t.Parallel()
+
+	const (
+		denied = "192.0.2.50" // in SWWAF_DENY_NETS
+		banned = otherClient  // under a ban read from bans.json
+	)
+
+	for _, tc := range []struct {
+		setting string // "" leaves SWWAF_MODE at its default
+		observe bool
+	}{
+		{"", false},
+		{"enforce", false},
+		{observe, true},
+	} {
+		t.Run(mode+"="+tc.setting, func(t *testing.T) {
+			t.Parallel()
+
+			geojsURL, _ := startGeoJS(t)
+			env := map[string]string{
+				rateLimitPerMinute: "1",
+				denyNets:           denied,
+				deniedCountries:    "kp",
+			}
+
+			if tc.setting != "" {
+				env[mode] = tc.setting
+			}
+
+			s, clk, server := startWithClock(t, geojsURL, env)
+			server.Ledger.Load([]bans.Ban{{
+				Netblock: netip.MustParsePrefix(banned + "/32"),
+				Start:    clk.Now(),
+				Expires:  clk.Now().Add(time.Hour),
+			}})
+
+			// fromDE's first request is within the limit of one a minute,
+			// and its second breaks it.
+			s.get(fromDE, http.StatusOK, requestlog.ActionForward)
+
+			for _, sent := range []struct{ from, refusal string }{
+				{denied, requestlog.ActionDenied},
+				{banned, requestlog.ActionBanned},
+				{fromKP, requestlog.ActionCountryDenied},
+				{fromDE, requestlog.ActionRateLimited},
+			} {
+				if !tc.observe {
+					line := s.get(sent.from, http.StatusForbidden, sent.refusal)
+					wantWouldAction(t, line, "")
+
+					continue
+				}
+
+				// Passed to the app, which answered it.
+				line := s.get(sent.from, http.StatusOK, requestlog.ActionForward)
+				wantWouldAction(t, line, sent.refusal)
+
+				if line.UpstreamStatus != http.StatusOK {
+					t.Errorf("log line has upstream_status %d, want 200",
+						line.UpstreamStatus)
+				}
+			}
+		})
+	}
+}
+
+func TestObserveModeMakesNoBanAndKeepsTheBansItHas(t *testing.T) {
+	t.Parallel()
+
+	s, clk, server := startWithClock(t, "", map[string]string{
+		mode:               observe,
+		rateLimitPerMinute: "1",
+	})
+	kept := bans.Ban{
+		Netblock: netip.MustParsePrefix(otherClient + "/32"),
+		Start:    clk.Now(),
+		Expires:  clk.Now().Add(time.Hour),
+	}
+	server.Ledger.Load([]bans.Ban{kept})
+
+	// No ban sets client's counters back to zero, so each request after
+	// the first breaks the limit of one a minute.
+	s.get(client, http.StatusOK, requestlog.ActionForward)
+
+	for range 2 {
+		line := s.get(client, http.StatusOK, requestlog.ActionForward)
+		wantWouldAction(t, line, requestlog.ActionRateLimited)
+
+		if line.LimitHit != minute || line.Offence != requestlog.OffenceLimit ||
+			line.BanExpires != "" {
+			t.Errorf("log line has limit_hit %q, offence %q and ban_expires %q, "+
+				"want minute, limit and none", line.LimitHit, line.Offence,
+				line.BanExpires)
+		}
+	}
+
+	// The ban read from bans.json refuses nothing, and so counts no
+	// refusal in its notes, but is kept.
+	line := s.get(otherClient, http.StatusOK, requestlog.ActionForward)
+	wantWouldAction(t, line, requestlog.ActionBanned)
+
+	if line.BanExpires != requestlog.FormatTime(kept.Expires) {
+		t.Errorf("log line has ban_expires %q, want %s", line.BanExpires,
+			requestlog.FormatTime(kept.Expires))
+	}
+
+	got := server.Ledger.Snapshot()
+	if len(got) != 1 || got[0] != kept {
+		t.Errorf("bans\n%+v\nwant only\n%+v", got, kept)
+	}
+}
+
+func TestObserveModeKeepsTheSizeLimitsAndTheToken(t *testing.T) {
+	t.Parallel()
+
+	const denied = "192.0.2.50" // in SWWAF_DENY_NETS
+
+	var calls atomic.Int32
+
+	app := startApp(t, func(w http.ResponseWriter, _ *http.Request) {
+		calls.Add(1)
+		answerWithSize(w, 2*sizeLimit, true)
+	})
+	addr, out := startProxy(t, app.URL, map[string]string{
+		mode:             observe,
+		trustedProxies:   trustLocalhost,
+		denyNets:         denied,
+		requestMaxBytes:  sizeLimitSetting,
+		responseMaxBytes: sizeLimitSetting,
+		metricsToken:     token,
+	})
+
+	// SWWAF_DENY_NETS would refuse each request; instead a size limit or
+	// the missing token does.
+	for i, tc := range []struct {
+		method, path string
+		body         io.Reader
+		status       int
+		action       string
+	}{
+		{
+			http.MethodPost, "/upload", bytes.NewReader(make([]byte, 2*sizeLimit)),
+			http.StatusRequestEntityTooLarge, requestlog.ActionTooLarge,
+		},
+		{
+			http.MethodGet, "/download", http.NoBody,
+			http.StatusBadGateway, requestlog.ActionTooLarge,
+		},
+		{
+			http.MethodGet, proxy.MetricsPath, http.NoBody,
+			http.StatusUnauthorized, requestlog.ActionAdmin,
+		},
+	} {
+		req := newRequest(t, tc.method, addr, tc.path, tc.body)
+		req.Header.Set(forwardedFor, denied)
+		wantStatus(t, do(t, req), tc.status)
+
+		line := out.requestLines(t, i+1)[i]
+		wantLine(t, line, tc.status, tc.action)
+		wantWouldAction(t, line, requestlog.ActionDenied)
+	}
+
+	// The upload was refused before it reached the app.
+	if calls.Load() != 1 {
+		t.Errorf("the app was called %d times, want once", calls.Load())
+	}
+}
+
+// wantWouldAction checks the request log line's would_action, and that a
+// line that should have none has no such field.
+func wantWouldAction(t *testing.T, line logLine, want string) {
+	t.Helper()
+
+	got, present := line.fields["would_action"]
+
+	switch {
+	case want == "" && present:
+		t.Errorf("log line has would_action %v, want none", got)
+	case want != "" && got != want:
+		t.Errorf("log line has would_action %v, want %s", got, want)
+	}
+}

internal/proxy/proxy_test.go

@@ -50,6 +50,7 @@ const (
 	clientResponseTimeout   = "SWWAF_CLIENT_RESPONSE_TIMEOUT"
 	upstreamRequestTimeout  = "SWWAF_UPSTREAM_REQUEST_TIMEOUT"
 	upstreamResponseTimeout = "SWWAF_UPSTREAM_RESPONSE_TIMEOUT"
+	mode                    = "SWWAF_MODE"
 	requestMaxBytes         = "SWWAF_REQUEST_MAX_BYTES"
 	responseMaxBytes        = "SWWAF_RESPONSE_MAX_BYTES"
 	trustedProxies          = "SWWAF_TRUSTED_PROXIES"

internal/proxy/request.go

@@ -109,38 +109,24 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
 
 // check is the one place where a request can be refused once its client
 // is known, before its body is read or anything reaches the app. It
-// returns nil to let the request through. A client in SWWAF_ALLOW_NETS
-// skips every check but the size limit. For any other client,
-// SWWAF_DENY_NETS comes first, then a ban on its netblock, so that a
-// client either refuses is not looked up, and then the country lists; a
-// request any of them refuses is not counted for the rate limits. Then
-// come the rate limits, unless the client is in
-// SWWAF_RATE_LIMIT_EXEMPT_NETS, so that every other request is counted,
-// one refused for its size too. Every refusal but the size limit's is
-// answered with SWWAF_BAN_RESPONSE. ctx is the request's own context.
+// returns nil to let the request through. The checks of checkClient come
+// first, answered with SWWAF_BAN_RESPONSE, and then the size limit, so
+// that a request the rate limits count is counted even when it is
+// refused for its size. In observe mode a request checkClient refuses
+// goes on to the size limit like any other. ctx is the request's own
+// context.
 func (rq *request) check(ctx context.Context) *refusal {
-	cfg := rq.h.config
-	allowed := isInside(rq.client, cfg.AllowNets)
-	exempt := isInside(rq.client, cfg.RateLimitExemptNets)
-	now := rq.h.now()
+	action := rq.checkClient(ctx)
+	if action != "" {
+		if !rq.h.config.Observe {
+			return rq.banResponse(action)
+		}
 
-	if !allowed && isInside(rq.client, cfg.DenyNets) {
-		return rq.banResponse(requestlog.ActionDenied)
+		// The log line names what enforce mode would have done.
+		rq.line.WouldAction = action
 	}
 
-	if !allowed && rq.banned(now) {
-		return rq.banResponse(requestlog.ActionBanned)
-	}
-
-	if !allowed && rq.countryDenied(ctx) {
-		return rq.banResponse(requestlog.ActionCountryDenied)
-	}
-
-	if !allowed && !exempt && rq.limitBroken(now) {
-		return rq.banResponse(requestlog.ActionRateLimited)
-	}
-
-	maxBytes := cfg.RequestMaxBytes
+	maxBytes := rq.h.config.RequestMaxBytes
 	if maxBytes > 0 && rq.in.ContentLength > maxBytes {
 		return &refusal{
 			status: http.StatusRequestEntityTooLarge,
@@ -152,6 +138,42 @@ func (rq *request) check(ctx context.Context) *refusal {
 	return nil
 }
 
+// checkClient runs the checks on the request's client, and returns the
+// action of the first that refuses the request, or "" when none does. A
+// client in SWWAF_ALLOW_NETS skips them. For any other client,
+// SWWAF_DENY_NETS comes first, then a ban on its netblock, so that a
+// client either refuses is not looked up, and then the country lists; a
+// request any of them refuses is not counted for the rate limits. Then
+// come the rate limits, unless the client is in
+// SWWAF_RATE_LIMIT_EXEMPT_NETS, so that every other request is counted.
+// ctx is the request's own context.
+func (rq *request) checkClient(ctx context.Context) string {
+	cfg := rq.h.config
+	if isInside(rq.client, cfg.AllowNets) {
+		return ""
+	}
+
+	now := rq.h.now()
+
+	if isInside(rq.client, cfg.DenyNets) {
+		return requestlog.ActionDenied
+	}
+
+	if rq.banned(now) {
+		return requestlog.ActionBanned
+	}
+
+	if rq.countryDenied(ctx) {
+		return requestlog.ActionCountryDenied
+	}
+
+	if !isInside(rq.client, cfg.RateLimitExemptNets) && rq.limitBroken(now) {
+		return requestlog.ActionRateLimited
+	}
+
+	return ""
+}
+
 // forward passes the request to the app and the app's answer back. ctx
 // is the request's own context.
 func (rq *request) forward(ctx context.Context) {