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,75 +86,6 @@ 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,12 +261,6 @@ 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
 	}
@@ -795,9 +789,19 @@ func (rq *request) responseTimedOut() {
 	}
 }
 
-// responseReceived is called once the app has sent its whole answer.
+// 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.
 func (rq *request) responseReceived() {
 	rq.complete = true
+
+	if rq.body != nil && !rq.body.received.Load() {
+		return
+	}
+
 	rq.stopTimers()
 }
 

internal/proxy/timeouts_test.go

@@ -194,6 +194,28 @@ 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()