A client that stops sending with little of its body left after the app has answered is timed out (closes #136)

When less than 256 KiB of a client's body is left after the app has
answered, the rest is read by closing the body, which the transport,
ReverseProxy and Go's server each do, not through requestBody.Read.
waiting was then false, so a request timeout that ran out took the 504
branch, which set no read deadline, and the request held its connection
for as long as the client kept it open. Once the app has answered, that
branch now ends reading the client's body at once, whichever of
SWWAF_CLIENT_REQUEST_TIMEOUT and SWWAF_UPSTREAM_REQUEST_TIMEOUT ran out.

Model: opus-5-5

internal/bans/admin_test.go

@@ -61,6 +61,59 @@ func TestAdminsBansAreNeverDroppedAndDoNotCountTowardMaxBans(t *testing.T) {
 	wantBans(t, ledger, map[netip.Prefix]int{adminsOnly: 2, both: 1, second: 0, third: 1})
 }
 
+func TestEarlierBansCountABanDroppedAfterAnAdminsBan(t *testing.T) {
+	t.Parallel()
+
+	rules := defaultRules()
+	rules.MaxBans = 2
+	ledger := bans.New(rules)
+	netblock := netip.MustParsePrefix("203.0.113.1/32")
+	other := netip.MustParsePrefix("203.0.113.2/32")
+
+	// An admin bans the netblock for a minute, and it then breaks a limit
+	// twice, each time after its last ban has ended.
+	ledger.BanForAdmin(netblock, midnight(), midnight().Add(time.Minute),
+		"probes for logins")
+	first, _ := ledger.BanForLimit(netblock, midnight().Add(time.Minute), bans.Notes{})
+	second, _ := ledger.BanForLimit(netblock, first.Expires, bans.Notes{})
+
+	// A ban on another netblock fills the ledger, and the netblock's first
+	// ban for a limit, its earliest that is not an admin's, goes.
+	ledger.BanForLimit(other, second.Start, bans.Notes{})
+	wantBans(t, ledger, map[netip.Prefix]int{netblock: 2, other: 1})
+
+	// The netblock's next ban still counts it.
+	third, _ := ledger.BanForLimit(netblock, second.Expires, bans.Notes{})
+	if third.Notes.EarlierBans != (bans.EarlierBans{Limit: 2, Admin: 1}) {
+		t.Errorf("the third ban for a limit has earlier bans %+v, "+
+			"want 2 for a limit and 1 an admin's", third.Notes.EarlierBans)
+	}
+}
+
+func TestEarlierBansCountABanAnAdminKeepsOnce(t *testing.T) {
+	t.Parallel()
+
+	ledger := bans.New(defaultRules())
+	netblock := netip.MustParsePrefix("203.0.113.1/32")
+
+	// The netblock breaks a limit twice, the second time after its first
+	// ban has ended, and the second ban's notes count the first. An admin
+	// then keeps the first ban.
+	first, _ := ledger.BanForLimit(netblock, midnight(), bans.Notes{})
+	second, _ := ledger.BanForLimit(netblock, first.Expires, bans.Notes{})
+
+	kept := first
+	kept.Cause = bans.CauseAdmin
+	ledger.LoadEdit([]bans.Ban{kept, second})
+
+	// The netblock's next ban counts the kept ban once, as an admin's.
+	third, _ := ledger.BanForLimit(netblock, second.Expires, bans.Notes{})
+	if third.Notes.EarlierBans != (bans.EarlierBans{Limit: 1, Admin: 1}) {
+		t.Errorf("the third ban for a limit has earlier bans %+v, "+
+			"want 1 for a limit and 1 an admin's", third.Notes.EarlierBans)
+	}
+}
+
 func TestReasonOfTheBansSmallwebwafMakes(t *testing.T) {
 	t.Parallel()
 

internal/bans/bans.go

@@ -687,26 +687,51 @@ func (l *Ledger) ban(
 }
 
 // earlierBans returns how many bans a netblock with the bans held, oldest
-// first, has had, by cause: the first ban held counts the bans the
+// first, has had, by cause. Each ban held gives a count: the bans its
-// netblock had before that one, since dropped to make room, and each ban
+// notes count before it, and one for it and each ban held after it. A
-// held adds one.
+// ban's count misses a ban dropped after it to make room, and that of an
+// admin's ban added to bans.json without notes misses the bans before it,
+// so the count that names the most bans is taken, whole: a ban an admin
+// keeps by giving it CauseAdmin is still counted under its old cause in
+// later bans' notes, and taking each cause from another count would count
+// it twice.
 func earlierBans(held []Ban) EarlierBans {
-	earlier := held[0].Notes.EarlierBans
+	// fromHere counts ban and the bans held after it.
+	var most, fromHere EarlierBans
 
-	for _, ban := range held {
+	for _, ban := range slices.Backward(held) {
 		switch ban.Cause {
 		case CauseLimit:
-			earlier.Limit++
+			fromHere.Limit++
 		case CauseAttack:
-			earlier.Attack++
+			fromHere.Attack++
 		case CauseAdmin:
-			earlier.Admin++
+			fromHere.Admin++
 		case CauseCrowdSec:
-			earlier.CrowdSec++
+			fromHere.CrowdSec++
+		}
+
+		notes := ban.Notes.EarlierBans
+		count := EarlierBans{
+			Limit:    notes.Limit + fromHere.Limit,
+			Attack:   notes.Attack + fromHere.Attack,
+			Admin:    notes.Admin + fromHere.Admin,
+			CrowdSec: notes.CrowdSec + fromHere.CrowdSec,
+		}
+
+		// Of counts that name as many bans, the earlier ban's is taken: it
+		// counts more of the bans held by the cause they have now.
+		if count.total() >= most.total() {
+			most = count
 		}
 	}
 
-	return earlier
+	return most
+}
+
+// total returns how many bans e counts, of all causes.
+func (e EarlierBans) total() int {
+	return e.Limit + e.Attack + e.Admin + e.CrowdSec
 }
 
 // markChanged has Changed receive a value, unless one is waiting already.

internal/proxy/request.go

@@ -710,6 +710,16 @@ func (rq *request) requestTimedOut(limit string) {
 	}
 
 	if rq.body == nil || !rq.body.waiting.Load() {
+		// Once the app has answered, the transport, ReverseProxy and Go's
+		// server each close the client's body, and closing it reads what
+		// is left of a body under 256 KiB without requestBody.Read, so
+		// waiting is false while that read waits for the client. That
+		// read ends now, before refuse: should smallwebwaf still answer
+		// itself, answer then sets the deadline it gives its own answers.
+		if !rq.answerStarted.IsZero() {
+			rq.stopReadingBody(time.Now())
+		}
+
 		rq.refuse(refusal{
 			status: http.StatusGatewayTimeout,
 			action: requestlog.ActionTimedOut,

internal/proxy/timeouts_test.go

@@ -7,6 +7,7 @@ import (
 	"net/http"
 	"net/http/httptest"
 	"strconv"
+	"strings"
 	"sync"
 	"sync/atomic"
 	"testing"
@@ -248,6 +249,93 @@ func TestClientStopsSendingAfterTheAppHasAnswered(t *testing.T) {
 	wantLimitHits(t, addr, clientRequestTimeout, 1)
 }
 
+func TestClientStopsSendingWithLittleOfItsBodyLeft(t *testing.T) {
+	t.Parallel()
+
+	for _, tc := range []struct {
+		name string
+		// limit is the setting set to shortTimeout, which runs out, and
+		// clientTimeout what SWWAF_CLIENT_REQUEST_TIMEOUT is set to when it
+		// is not limit.
+		limit, clientTimeout string
+	}{
+		{
+			name:  "client request timeout",
+			limit: clientRequestTimeout,
+		},
+		{
+			name:          "upstream request timeout, client request timeout off",
+			limit:         upstreamRequestTimeout,
+			clientTimeout: off,
+		},
+		{
+			name:          "upstream request timeout, client request timeout longer",
+			limit:         upstreamRequestTimeout,
+			clientTimeout: longTimeoutSetting,
+		},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+
+			// appClosed is closed once smallwebwaf has closed its
+			// connection to the app, which it does once it has the app's
+			// answer.
+			appClosed := make(chan struct{})
+
+			// The app takes the bytes the client sent, so that smallwebwaf
+			// is waiting for the client to send more, and then answers
+			// without reading the rest of the body, and says it closes the
+			// connection.
+			app := startApp(t, func(w http.ResponseWriter, _ *http.Request) {
+				conn, buf, err := http.NewResponseController(w).Hijack()
+				if err != nil {
+					return
+				}
+
+				_, _ = io.ReadFull(buf.Reader, make([]byte, len("the first bytes")))
+				_, _ = buf.WriteString("HTTP/1.1 404 Not Found\r\n" +
+					"Content-Length: 0\r\nConnection: close\r\n\r\n")
+				_ = buf.Flush()
+				_, _ = io.Copy(io.Discard, buf.Reader)
+				_ = conn.Close()
+
+				close(appClosed)
+			})
+
+			env := map[string]string{tc.limit: shortTimeoutSetting, metricsToken: token}
+			if tc.clientTimeout != "" {
+				env[clientRequestTimeout] = tc.clientTimeout
+			}
+
+			addr, out := startProxy(t, app.URL, env)
+
+			// Less than 256 KiB of the body is left after the first bytes,
+			// little enough for Go's server in smallwebwaf to read the rest
+			// itself before it sends the app's answer.
+			start := time.Now()
+			conn := dial(t, addr)
+			send(t, conn, "POST /upload HTTP/1.1\r\nHost: app\r\nContent-Length: 200000\r\n\r\n"+
+				"the first bytes")
+
+			select {
+			case <-appClosed:
+			case <-time.After(waitLimit):
+				t.Fatal("smallwebwaf did not close its connection to the app")
+			}
+
+			// More of the body, which can no longer go to the app, and then
+			// nothing.
+			send(t, conn, strings.Repeat("x", 8<<10))
+
+			got := readResponse(t, conn)
+			wantTimedOut(t, start)
+			wantStatus(t, got, http.StatusNotFound)
+			wantLine(t, out.requestLine(t), http.StatusNotFound, requestlog.ActionTimedOut)
+			wantLimitHits(t, addr, tc.limit, 1)
+		})
+	}
+}
+
 func TestAppTooSlowToAnswer(t *testing.T) {
 	t.Parallel()