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/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)
+	}
+}