A request that waited for its lookup is counted when it goes on (closes #129)

checkClient read the time before the lookup, which can wait for GeoJS
up to SWWAF_LOOKUP_TIMEOUT, and the rate limits counted the request at
that time. Two requests of a new client waiting across the end of a
minute could then be counted out of order, and the one dated more than a
second before the minute under way began made the rate limits start
that window afresh, as for a clock set back: the other request's count
was lost. The checks after the lookup now read the time again.

Model: opus-5-5

internal/proxy/lookup_test.go

@@ -86,6 +86,75 @@ func TestEveryClientIsLookedUpWithoutWaitingWhileNoSettingNeedsIt(t *testing.T)
 	}
 }
 
+func TestRequestThatWaitedForItsLookupIsCountedWhenItGoesOn(t *testing.T) {
+	t.Parallel()
+
+	// The country list has a new client's request wait for its answer,
+	// which the stand-in for GeoJS gives only once released.
+	geojsURL, asked, release := startHeldGeoJS(t)
+	app := startApp(t, func(http.ResponseWriter, *http.Request) {})
+	clk := &clock{now: time.Date(2026, 10, 6, 0, 0, 58, 0, time.UTC)}
+	addr, out, server := startProxyWithClock(t, app.URL, geojsURL, clk.Now,
+		map[string]string{
+			trustedProxies:  trustLocalhost,
+			lookupTimeout:   "1h",
+			deniedCountries: "kp",
+		})
+
+	requestFromDE := func() *http.Request {
+		req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
+		req.Header.Set(forwardedFor, fromDE)
+
+		return req
+	}
+
+	// fromDE's first request arrives two seconds before a minute ends,
+	// and waits for GeoJS.
+	first, httpClient := requestFromDE(), newClient(t)
+	firstEnded := make(chan error, 1)
+
+	go func() {
+		res, err := httpClient.Do(first)
+		if err == nil {
+			err = readAnswer(res).err
+		}
+
+		firstEnded <- err
+	}()
+
+	waitUntil(func() bool { return len(asked()) == 1 })
+
+	// Half a second into the next minute, the answer is kept, as an edit
+	// of lookups.json would keep it, while the first request still waits
+	// for GeoJS. The second request goes on at once, and is counted.
+	clk.advance(2500 * time.Millisecond)
+	server.GeoJS.Load([]lookup.Answer{{
+		Client: netip.MustParsePrefix(fromDE + "/32"), ASN: asnDE, ASName: asNameDE,
+		Country: "DE", Answered: clk.Now(), Used: clk.Now(),
+	}})
+	wantStatus(t, do(t, requestFromDE()), http.StatusOK)
+
+	// GeoJS answers, and the first request goes on.
+	release()
+
+	err := <-firstEnded
+	if err != nil {
+		t.Fatalf("first request: %v", err)
+	}
+
+	wantLine(t, out.requestLines(t, 2)[1], http.StatusOK, requestlog.ActionForward)
+
+	// The third request's count holds all three: the first was counted
+	// when it went on, in the minute under way, and the second's count
+	// was kept.
+	clk.advance(500 * time.Millisecond)
+	wantStatus(t, do(t, requestFromDE()), http.StatusOK)
+
+	if got := out.requestLines(t, 3)[2].Counts.Minute; got != 3 {
+		t.Errorf("the third request's count in the minute is %v, want 3", got)
+	}
+}
+
 func TestASNumberAndNameInTheLogLineTheHistoryTheBanNotesAndTheAlert(t *testing.T) {
 	t.Parallel()
 

internal/proxy/request.go

@@ -261,6 +261,12 @@ func (rq *request) checkClient(ctx context.Context) string {
 
 	rq.lookUp(ctx)
 
+	// The lookup can wait for GeoJS, so the checks after it read the time
+	// again: a request counted at the time it arrived could be counted
+	// after a later one of its client's, which the rate limits would take
+	// for the clock set back.
+	now = rq.h.now()
+
 	if rq.countryDenied() {
 		return requestlog.ActionCountryDenied
 	}
@@ -789,19 +795,9 @@ func (rq *request) responseTimedOut() {
 	}
 }
 
-// responseReceived is called once the app has sent its whole answer. An
-// app may answer before the client has sent its whole body, as with a 404
-// it sends without reading it. The timeouts then run on: until the
-// transport's read of the body returns, Go's server cannot send the
-// answer, and SWWAF_CLIENT_REQUEST_TIMEOUT is what ends that read for a
-// client that stops sending.
+// responseReceived is called once the app has sent its whole answer.
 func (rq *request) responseReceived() {
 	rq.complete = true
-
-	if rq.body != nil && !rq.body.received.Load() {
-		return
-	}
-
 	rq.stopTimers()
 }
 

internal/proxy/timeouts_test.go

@@ -194,28 +194,6 @@ func sendLargeBody(t *testing.T, addr string) net.Conn {
 	return conn
 }
 
-func TestClientStopsSendingAfterTheAppHasAnswered(t *testing.T) {
-	t.Parallel()
-
-	// The app answers at once without reading the body, as an app does
-	// for a path it does not serve.
-	app := startApp(t, http.NotFound)
-	addr, out := startProxy(t, app.URL, map[string]string{
-		clientRequestTimeout: shortTimeoutSetting,
-		metricsToken:         token,
-	})
-
-	start := time.Now()
-	got := readResponse(t, sendPartOfBody(t, addr))
-	wantTimedOut(t, start)
-
-	// The app's answer came before the time ran out, so the client is
-	// sent that answer, not smallwebwaf's 408.
-	wantStatus(t, got, http.StatusNotFound)
-	wantLine(t, out.requestLine(t), http.StatusNotFound, requestlog.ActionTimedOut)
-	wantLimitHits(t, addr, clientRequestTimeout, 1)
-}
-
 func TestAppTooSlowToAnswer(t *testing.T) {
 	t.Parallel()