A client that stops sending after the app answers is timed out (closes #130)

When the app answered before the client had sent its whole body, and its
answer ended with its last bytes, every timeout was stopped,
SWWAF_CLIENT_REQUEST_TIMEOUT included. The transport went on waiting to
read the body, and Go's server cannot send the answer until that read
returns, so a client that stopped sending held the request until it
closed the connection. The timeouts now run on until the client has sent
its body, as they do before the app answers: once
SWWAF_CLIENT_REQUEST_TIMEOUT runs out the client is sent the app's
answer, the connection is closed, and the log line says timed_out.

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
 	}