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

SPEC.md

@@ -2326,7 +2326,8 @@ but for these headers:
   claims and are replaced. `X-Forwarded-For` names the peer, `X-Forwarded-Host`
   the host it asked for, and `X-Forwarded-Proto` plain `http`. Every other
   header whose name starts with `X-Forwarded-` is removed, and so are
-  `Forwarded` and `X-Real-IP`.
+  `Forwarded` and `X-Real-IP`. A name spelt with `_` for `-`, such as
+  `X_Forwarded_Ssl`, counts as the same name.
 - `X-Request-ID`, which carries the fresh id.
 - `X-Client-ASN` and `X-Client-Country`, which carry what `waf` answered. A
   header it did not give is left out. Any of the two the visitor sent is

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,19 +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()
 	})
-
-	// Route answers no_answer_yet while the query is under way, and
-	// request_failed once it has failed, after queryTimeout.
-	if _, missing := f.route(); missing != routewatch.NoAnswerYet {
-		t.Errorf("Route gave %q while routewatch hangs, want %q",
-			missing, routewatch.NoAnswerYet)
-	}
-
-	f.waitFor(routewatch.RequestFailed)
-	f.wantFailureLoggedWithoutTheClient()
 }
 
 func TestRepeatedRequestsMakeOneQueryAndTheAnswerExpires(t *testing.T) {

internal/rproxy/client.go

@@ -105,17 +105,16 @@ func setForwardedHeaders(in, out *http.Request, peer netip.Addr, trusted bool) {
 		return
 	}
 
-	// ReverseProxy has removed Forwarded and the three set below. Go's server
-	// gives header names in canonical form, so the prefix matches the name in
-	// any letter case.
+	// An app behind CGI or FastCGI reads X_Forwarded_Ssl as X-Forwarded-Ssl, so
+	// a name is matched with each _ read as - and in any letter case.
 	for name := range out.Header {
-		if strings.HasPrefix(name, "X-Forwarded-") {
+		spelt := strings.ToLower(strings.ReplaceAll(name, "_", "-"))
+		if strings.HasPrefix(spelt, "x-forwarded-") ||
+			spelt == "forwarded" || spelt == "x-real-ip" {
 			delete(out.Header, name)
 		}
 	}
 
-	out.Header.Del("X-Real-IP")
-
 	out.Header.Set("X-Forwarded-For", forwardedFor)
 	out.Header.Set("X-Forwarded-Host", in.Host)
 	out.Header.Set("X-Forwarded-Proto", "http")

internal/rproxy/rproxy_test.go

@@ -561,6 +561,7 @@ func TestAPeerNotTrustedHasItsForwardedHeadersReplaced(t *testing.T) {
 		"X-Forwarded-Tls-Client-Cert-Info", "X-Real-Ip",
 		"X-Forwarded-Scheme", "X-Forwarded-Ssl", "X-Forwarded-Protocol",
 		"X-Forwarded-Path", "X-Forwarded-Client-Cert",
+		"X_Forwarded_Ssl", "X_Forwarded_Proto", "X_Real_IP",
 	}
 
 	standIn := startWAF(t, allow)
@@ -628,6 +629,7 @@ func TestATrustedProxysForwardedHeadersPassOn(t *testing.T) {
 		forwardedProtoHeader: "https",
 		"X-Real-Ip":          "198.51.100.1",
 		"X-Forwarded-Ssl":    "on",
+		"X_Forwarded_Ssl":    "on",
 	}
 
 	req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)

internal/waf/answertime_test.go

@@ -1,6 +1,7 @@
 package waf_test
 
 import (
+	"encoding/binary"
 	"fmt"
 	"maps"
 	"net"
@@ -8,8 +9,10 @@ import (
 	"net/http/httptest"
 	"net/netip"
 	"path/filepath"
+	"slices"
 	"strconv"
 	"strings"
+	"sync"
 	"testing"
 	"testing/synctest"
 	"time"
@@ -633,14 +636,7 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 
 	// 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")
-	if err != nil {
-		t.Fatalf("listen: %v", err)
-	}
-
-	t.Cleanup(func() { _ = resolver.Close() })
+	resolver, releaseResolver := startHeldResolver(t)
 
 	server, out, _ := newWAFWith(t, func(
 		params waf.Params,
@@ -650,7 +646,7 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 		return waf.New(params)
 	}, 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,
@@ -663,7 +659,8 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 	// 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 starts only after the wait for GeoJS.
+	// 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")
@@ -687,17 +684,77 @@ func TestWAFAnswersWithinTheTimeLimitWhileEveryOutsideSourceHangs(
 			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)
+		// 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 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.
+		// The query is answered, and the check with AbuseIPDB abandoned,
+		// before the bubble ends.
+		releaseResolver()
 		time.Sleep(defaultReputationWait)
 	})
 }
+
+// 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
+			}
+
+			<-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)
+		}
+	}()
+
+	release := func() { once.Do(func() { close(released) }) }
+	// Run before conn is closed, so that no query is left waiting.
+	t.Cleanup(release)
+
+	return conn.LocalAddr().String(), release
+}