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
 	}