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. A resolver stand-in
holds the DNS blocklist's query until the checks are done, so a waf that
waited for the query would answer only after it failed, which the test
catches.

The routewatch test for a hanging routewatch runs Route in a synctest
bubble, against a stand-in on Go's default transport, and requires
no_answer_yet after exactly zero time.

Model: opus-5-5

internal/routewatch/routewatch_test.go

@@ -11,6 +11,7 @@ import (
 	"sync"
 	"sync/atomic"
 	"testing"
+	"testing/synctest"
 	"time"
 
 	"sneak.berlin/go/smallwebwaf/internal/routewatch"
@@ -113,6 +114,28 @@ func answering(body string) http.HandlerFunc {
 	}
 }
 
+// silentURL is where a routewatch that never answers is: a query to it waits,
+// without the network, until it is abandoned. TestMain registers it with Go's
+// default transport, through which the Client asks.
+const silentURL = "silent://routewatch/"
+
+func TestMain(m *testing.M) {
+	transport, _ := http.DefaultTransport.(*http.Transport)
+	transport.RegisterProtocol("silent", silentRoutewatch{})
+
+	m.Run()
+}
+
+// silentRoutewatch is the routewatch at silentURL.
+type silentRoutewatch struct{}
+
+// RoundTrip waits until req is abandoned.
+func (silentRoutewatch) RoundTrip(req *http.Request) (*http.Response, error) {
+	<-req.Context().Done()
+
+	return nil, req.Context().Err()
+}
+
 func (f *fixture) route() (routewatch.Route, routewatch.Missing) {
 	addr := netip.MustParseAddr(clientAddr)
 	client := netip.PrefixFrom(addr, addr.BitLen())
@@ -287,20 +310,29 @@ func TestFailureIsKeptForAMinuteSoRoutewatchIsNotAskedPerRequest(t *testing.T) {
 func TestHangingRoutewatchNeverDelaysAndFailsTheQuery(t *testing.T) {
 	t.Parallel()
 
-	f := newFixture(t, func(_ http.ResponseWriter, r *http.Request) {
-		<-r.Context().Done()
+	// In a synctest bubble, time passes only while every goroutine in it waits,
+	// so Route's wait is measured exactly, however busy the host is. routewatch
+	// is the one at silentURL: one reached over the network would keep the
+	// bubble's clock from moving.
+	synctest.Test(t, func(t *testing.T) {
+		// Without newFixture's stand-in, which is reached over the network.
+		f := &fixture{t: t, log: &syncBuffer{}}
+		f.client = routewatch.New(routewatch.Params{
+			URL: silentURL, Now: time.Now,
+			ProcessLog: slog.New(slog.NewTextHandler(f.log, nil)),
+		})
+
+		began := time.Now()
+		_, missing := f.route()
+
+		if waited := time.Since(began); missing != routewatch.NoAnswerYet || waited != 0 {
+			t.Errorf("Route gave %q after %s while routewatch hangs, want %q at once",
+				missing, waited, routewatch.NoAnswerYet)
+		}
+
+		f.waitFor(routewatch.RequestFailed)
+		f.wantFailureLoggedWithoutTheClient()
 	})
-
-	start := time.Now()
-
-	f.route()
-
-	if elapsed := time.Since(start); elapsed > time.Second {
-		t.Errorf("Route took %s while routewatch hangs", elapsed)
-	}
-
-	f.waitFor(routewatch.RequestFailed)
-	f.wantFailureLoggedWithoutTheClient()
 }
 
 func TestRepeatedRequestsMakeOneQueryAndTheAnswerExpires(t *testing.T) {

internal/waf/answertime_test.go

@@ -1,6 +1,7 @@
 package waf_test
 
 import (
+	"encoding/binary"
 	"fmt"
 	"maps"
 	"net"
@@ -11,10 +12,13 @@ import (
 	"slices"
 	"strconv"
 	"strings"
+	"sync"
 	"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 +34,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,15 +634,9 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 ) {
 	t.Parallel()
 
-	held, askedGeoJS, _ := startHeldGeoJS(t)
-
-	// A resolver that takes every query and answers none.
-	resolver, err := (&net.ListenConfig{}).ListenPacket(t.Context(), "udp", localhost+":0")
-	if err != nil {
-		t.Fatalf("listen: %v", err)
-	}
-
-	t.Cleanup(func() { _ = resolver.Close() })
+	// The lists' stand-in: one for GeoJS that answers nothing.
+	held, _, _ := startHeldGeoJS(t)
+	resolver, releaseResolver := startHeldResolver(t)
 
 	server, out, _ := newWAFWith(t, func(
 		params waf.Params,
@@ -644,42 +644,117 @@ 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(),
+		dnsblZones: dnsblZone, dnsblResolver: resolver,
 		abuseIPDBKey:  accountKey,
 		blocklistURLs: held + "/drop.txt", asnLimitPercentURL: held + "/asn.txt",
 		crowdSecURL: held, crowdSecKey: bouncerKey,
 	})
 
-	// 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})
-
+	// The lists are fetched outside the synctest bubble below: a wait on the
+	// network inside it would keep its clock from moving on.
 	go server.Lists.Run(t.Context())
 
-	status, took := askDirectly(t, server, func(req *http.Request) {
-		req.Header.Set("User-Agent", "test")
-		req.Header.Set("Accept", "*/*")
-		req.Host = siteA
+	// In the bubble, as TestRequestWaitsAsLongAsTheLookupTimeoutSays says, the
+	// answer takes exactly as long as waf waits, however busy the host is.
+	// GeoJS and AbuseIPDB never answer there, without the network. The query to
+	// the DNS blocklist waits on the network, which stops the bubble's clock,
+	// but it 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)
+		}
+
+		// The resolver holds the query until it is released below, so a waf
+		// that waited for the query would answer only once it had failed.
+		queries, failures := server.DNSBL.Queries(dnsblZone), server.DNSBL.Failures(dnsblZone)
+		if queries != 1 || failures != 0 {
+			t.Errorf("%d queries to the DNS blocklist, %d failed, want 1, none failed",
+				queries, failures)
+		}
+
+		if checked := server.AbuseIPDB.Checked(); checked != 1 {
+			t.Errorf("%d checks with AbuseIPDB, want 1", checked)
+		}
+
+		// The query is answered, and the check with AbuseIPDB abandoned,
+		// before the bubble ends.
+		releaseResolver()
+		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())
+// How the stand-in for the resolver reads a query and makes it its reply.
+const (
+	// maxQueryLength is the longest query it reads.
+	maxQueryLength = 512
+	// flagsAt is where a DNS message's flags start, after its id.
+	flagsAt = 2
+	// noSuchNameFlags mark a reply, to a query that asked for recursion,
+	// which is available, that no such name exists.
+	noSuchNameFlags = 0x8183
+)
+
+// startHeldResolver starts a stand-in for the resolver the DNSBL zones are
+// asked through, and returns its address and release. Each query waits until
+// release is called, and is then answered that no such name exists, so that
+// the zone does not list the client.
+func startHeldResolver(t *testing.T) (string, func()) {
+	t.Helper()
+
+	conn, err := (&net.ListenConfig{}).ListenPacket(t.Context(), "udp", localhost+":0")
+	if err != nil {
+		t.Fatalf("listen: %v", err)
 	}
+
+	t.Cleanup(func() { _ = conn.Close() })
+
+	var (
+		released = make(chan struct{})
+		once     sync.Once
+	)
+
+	go func() {
+		query := make([]byte, maxQueryLength)
+
+		for {
+			n, from, err := conn.ReadFrom(query)
+			if err != nil {
+				return // conn is closed
+			}
 
-	// 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)
-	}
+			<-released
+
+			// The query back, with the flags of the reply in place of its own.
+			reply := slices.Clone(query[:n])
+			binary.BigEndian.PutUint16(reply[flagsAt:], noSuchNameFlags)
+
+			_, _ = conn.WriteTo(reply, from)
+		}
+	}()
 
-	if queries := server.DNSBL.Queries(dnsblZone); queries != 1 {
-		t.Errorf("%d queries to the DNS blocklist, want 1", queries)
-	}
+	release := func() { once.Do(func() { close(released) }) }
+	// Run before conn is closed, so that no query is left waiting.
+	t.Cleanup(release)
 
-	if checked := server.AbuseIPDB.Checked(); checked != 1 {
-		t.Errorf("%d checks with AbuseIPDB, want 1", checked)
-	}
+	return conn.LocalAddr().String(), release
 }