Answer-time tests check the answer, not wall-clock milliseconds (closes #316)

The waf test that asks a question while every outside source hangs now
runs it in a synctest bubble and checks that the answer comes after
exactly the GeoJS wait, within the time limit. GeoJS is the silent
stand-in; the lists are fetched outside the bubble. The routewatch test
for a hanging routewatch checks that Route answers no_answer_yet instead
of timing it.

Model: opus-5-5

internal/routewatch/routewatch_test.go

@@ -291,12 +291,11 @@ func TestHangingRoutewatchNeverDelaysAndFailsTheQuery(t *testing.T) {
 		<-r.Context().Done()
 	})
 
-	start := time.Now()
+	// Route answers no_answer_yet while the query is under way, and
-
+	// request_failed once it has failed, after queryTimeout.
-	f.route()
+	if _, missing := f.route(); missing != routewatch.NoAnswerYet {
-
+		t.Errorf("Route gave %q while routewatch hangs, want %q",
-	if elapsed := time.Since(start); elapsed > time.Second {
+			missing, routewatch.NoAnswerYet)
-		t.Errorf("Route took %s while routewatch hangs", elapsed)
 	}
 
 	f.waitFor(routewatch.RequestFailed)

internal/waf/answertime_test.go

@@ -8,13 +8,14 @@ import (
 	"net/http/httptest"
 	"net/netip"
 	"path/filepath"
-	"slices"
 	"strconv"
 	"strings"
 	"testing"
 	"testing/synctest"
 	"time"
 
+	"github.com/prometheus/client_golang/prometheus/testutil"
+
 	"sneak.berlin/go/smallwebwaf/internal/bans"
 	"sneak.berlin/go/smallwebwaf/internal/lookup"
 	"sneak.berlin/go/smallwebwaf/internal/lookup/lookuptest"
@@ -30,6 +31,8 @@ const (
 	answerTimeLimit = 2 * time.Second
 	// defaultLookupWait is the default of SWW_LOOKUP_TIMEOUT.
 	defaultLookupWait = 800 * time.Millisecond
+	// defaultReputationWait is the default of SWW_REPUTATION_TIMEOUT.
+	defaultReputationWait = 2 * time.Second
 	// The header limits SPEC.md gives.
 	cookieLimit      = 50
 	headerFieldLimit = 100
@@ -628,7 +631,8 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 ) {
 	t.Parallel()
 
-	held, askedGeoJS, _ := startHeldGeoJS(t)
+	// The lists' stand-in: one for GeoJS that answers nothing.
+	held, _, _ := startHeldGeoJS(t)
 
 	// A resolver that takes every query and answers none.
 	resolver, err := (&net.ListenConfig{}).ListenPacket(t.Context(), "udp", localhost+":0")
@@ -644,7 +648,7 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 		params.AbuseIPDBURL = silentAbuseIPDBURL
 
 		return waf.New(params)
-	}, held, time.Now, map[string]string{
+	}, silentGeoJSURL, time.Now, map[string]string{
 		tagDeny: "country=KP", wafMode: block,
 		dnsblZones: dnsblZone, dnsblResolver: resolver.LocalAddr().String(),
 		abuseIPDBKey:  accountKey,
@@ -652,34 +656,48 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 		crowdSecURL: held, crowdSecKey: bouncerKey,
 	})
 
-	// AbuseIPDB is asked only about a client with an offence.
+	// The lists are fetched outside the synctest bubble below: a wait on the
-	group := netip.MustParsePrefix(client + "/32")
+	// network inside it would keep its clock from moving on.
-	server.Limiter.AddToHistory(group, time.Now(), ratelimit.Request{Attack: true})
-
 	go server.Lists.Run(t.Context())
 
-	status, took := askDirectly(t, server, func(req *http.Request) {
+	// In the bubble, as TestRequestWaitsAsLongAsTheLookupTimeoutSays says, the
-		req.Header.Set("User-Agent", "test")
+	// answer takes exactly as long as waf waits, however busy the host is.
-		req.Header.Set("Accept", "*/*")
+	// GeoJS and AbuseIPDB never answer there, without the network. The query to
-		req.Host = siteA
+	// the DNS blocklist starts only after the wait for GeoJS.
+	synctest.Test(t, func(t *testing.T) {
+		// AbuseIPDB is asked only about a client with an offence.
+		group := netip.MustParsePrefix(client + "/32")
+		server.Limiter.AddToHistory(group, time.Now(), ratelimit.Request{Attack: true})
+
+		status, took := askDirectly(t, server, func(req *http.Request) {
+			req.Header.Set("User-Agent", "test")
+			req.Header.Set("Accept", "*/*")
+			req.Host = siteA
+		})
+
+		// The wait for GeoJS decides when the answer comes.
+		if status != http.StatusOK || took != defaultLookupWait || took >= answerTimeLimit {
+			t.Errorf("answered %d after %s, want %d after %s, within %s; output:\n%s",
+				status, took, http.StatusOK, defaultLookupWait, answerTimeLimit, out.text())
+		}
+
+		// Each outside source was asked, and none has answered. GeoJS is asked
+		// only about the clients waiting for it, here client alone.
+		if requests := testutil.ToFloat64(server.Metrics.GeoJSRequests); requests != 1 {
+			t.Errorf("%v requests to GeoJS, want 1", requests)
+		}
+
+		if queries := server.DNSBL.Queries(dnsblZone); queries != 1 {
+			t.Errorf("%d queries to the DNS blocklist, want 1", queries)
+		}
+
+		if checked := server.AbuseIPDB.Checked(); checked != 1 {
+			t.Errorf("%d checks with AbuseIPDB, want 1", checked)
+		}
+
+		// The check with AbuseIPDB is abandoned before the bubble ends. The
+		// bubble also waits for the query to the DNS blocklist to fail, which
+		// it does on the real clock, since the query waits on the network.
+		time.Sleep(defaultReputationWait)
 	})
-
-	if status != http.StatusOK || took >= answerTimeLimit {
-		t.Errorf("answered %d after %s, want %d within %s; output:\n%s",
-			status, took, http.StatusOK, answerTimeLimit, out.text())
-	}
-
-	// Each outside source was asked, and none has answered. The stand-in for
-	// GeoJS is the lists' too, which name no address.
-	if !slices.Contains(askedGeoJS(), client) {
-		t.Errorf("GeoJS was asked about %q, not %s", askedGeoJS(), client)
-	}
-
-	if queries := server.DNSBL.Queries(dnsblZone); queries != 1 {
-		t.Errorf("%d queries to the DNS blocklist, want 1", queries)
-	}
-
-	if checked := server.AbuseIPDB.Checked(); checked != 1 {
-		t.Errorf("%d checks with AbuseIPDB, want 1", checked)
-	}
 }