From f5d55028fe5ed4c3bde61f783486a00715844db2 Mon Sep 17 00:00:00 2001 From: sneak Date: Wed, 11 Nov 2026 07:10:25 +0000 Subject: [PATCH] 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 | 58 +++++++--- internal/waf/answertime_test.go | 141 +++++++++++++++++++------ 2 files changed, 153 insertions(+), 46 deletions(-) diff --git a/internal/routewatch/routewatch_test.go b/internal/routewatch/routewatch_test.go index c74b1af..aed1b6e 100644 --- a/internal/routewatch/routewatch_test.go +++ b/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) { diff --git a/internal/waf/answertime_test.go b/internal/waf/answertime_test.go index bf5bd4c..5ae3eed 100644 --- a/internal/waf/answertime_test.go +++ b/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 }