README and SPEC say a client too slow to send its request line and headers may get an error answer (closes #138)

A client too slow to send its request line and headers within
SWWAF_CLIENT_REQUEST_TIMEOUT gets either no answer or an error answer
from Go's server, mostly 400 Bad Request; either way its connection is
closed, nothing reaches the app, and no request log line is written.
The README's "Request log" and SPEC's size and time limits said such a
client always gets no answer. Both documents' summaries of
smallwebwaf's own answers now cover only limits passed after the
request line and headers have been read, and give 408 only for a slow
body; SPEC names Go's server as the one answering 431.

Model: opus-5-5

README.md

@@ -96,11 +96,14 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set, and the default rule file of
 ## What it does so far
 
 - Passes each request to the app and the app's answer back unchanged: method,
-  path, query, headers, body and status. Bodies stream through in both
+  path, query, headers, body and status. The one exception is a path starting
-  directions and are never held whole in memory, but for the part of a request
+  with `//` that holds a character Go escapes, such as `|`: Go cannot send it as
-  body the Core Rule Set reads, at most `SWWAF_WAF_BODY_LIMIT` and one byte
+  it is, and the app receives it decoded and escaped again, `%2F` as `/`. Bodies
-  more, which is held until the app is sent it. A WebSocket, or any other
+  stream through in both directions and are never held whole in memory, but for
-  upgraded connection, passes through, and the timeouts do not cut it.
+  the part of a request body the Core Rule Set reads, at most
+  `SWWAF_WAF_BODY_LIMIT` and one byte more, which is held until the app is sent
+  it. A WebSocket, or any other upgraded connection, passes through, and the
+  timeouts do not cut it.
 - Works out the client's address. A TCP peer outside `SWWAF_TRUSTED_PROXIES` is
   the client, and the forwarded headers it sends are replaced, not passed on.
   For a peer inside it, `X-Forwarded-For` is read from the right, and the first
@@ -110,16 +113,16 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set, and the default rule file of
   `X-Forwarded-Proto`, and `X-Forwarded-For` with the peer added at the end. It
   also gets the request's id in `X-Request-ID`, the same id as in the request's
   log line (see `request_id` in "Request log" below).
-- Enforces the timeouts and the size limits below. A limit passed before the
+- Enforces the timeouts and the size limits below. Once a request's line and
-  response has started gets `smallwebwaf`'s own answer: `408` for a client too
+  headers have been read, a limit passed before the response has started gets
-  slow to send its request, `413` for a request body that is too large, `504`
+  `smallwebwaf`'s own answer: `408` for a client too slow to send its body,
-  for an app too slow to answer, and `502` for a response that is too large or
+  `413` for a request body that is too large, `504` for an app too slow to
-  an app that cannot be reached. A request that announces a body over the limit
+  answer, and `502` for a response that is too large or an app that cannot be
-  is refused before anything reaches the app. While a request body is still on
+  reached. A request that announces a body over the limit is refused before
-  its way, a request timeout that runs out answers `408` if `smallwebwaf` was
+  anything reaches the app. While a request body is still on its way, a request
-  waiting for the client to send more, and `504` if it was waiting for the app
+  timeout that runs out answers `408` if `smallwebwaf` was waiting for the
-  to take what it had. Once the response has started, a limit can only cut the
+  client to send more, and `504` if it was waiting for the app to take what it
-  connection.
+  had. Once the response has started, a limit can only cut the connection.
 - Counts each client's requests over a minute, an hour and a day. A request that
   takes the client over one of the rate limits below is refused with
   `SWWAF_BAN_RESPONSE`, `403` by default, before anything reaches the app, and
@@ -1042,9 +1045,11 @@ less severe than `SWWAF_LOG_LEVEL` are not written.
 Go's HTTP server, on which `smallwebwaf` is built, reads a request's line and
 headers before `smallwebwaf` sees the request, and some requests end there,
 without a line in the log: headers over `SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES`,
-which it answers `431`, headers slower than `SWWAF_CLIENT_REQUEST_TIMEOUT`,
+which it answers `431`, and requests it cannot read at all, which it answers
-whose connection it closes without an answer, and requests it cannot read at
+itself, mostly with `400`. A client too slow to send its request line and
-all, which it answers itself, mostly with `400`.
+headers within `SWWAF_CLIENT_REQUEST_TIMEOUT` gets either no answer or an error
+answer from the server, mostly `400 Bad Request`; either way the server closes
+its connection, nothing reaches the app, and no line is written in the log.
 
 ### Sending the log to a syslog server
 
@@ -1954,8 +1959,14 @@ main "$@"
   without one, it still starts. At each start the `run` script of `smallwebwaf`
   gives that directory and every file in it to the `smallwebwaf` user, so a host
   directory mounted there needs no change of owner.
-- `docker stop` has runit stop both processes. `smallwebwaf` then stops taking
+- `docker stop` has runit stop both processes at once, each with SIGTERM.
-  requests and gives those in progress five seconds to finish.
+  `smallwebwaf` then stops taking requests and gives those in progress five
+  seconds to finish, which they can do only while the app still answers. An app
+  that exits at once on SIGTERM ends them: the client gets `502`, or a response
+  cut short if the app had already begun to answer. An app that should let them
+  finish keeps taking and answering requests, not only the ones it already has,
+  for the whole five seconds after SIGTERM, since `smallwebwaf` can still pass
+  it requests it took before then.
 
 A rule file is one rule per line: a name, what to match against, what to do, and
 a regex.

SPEC.md

@@ -414,10 +414,10 @@ The settings, by group:
       to send its request line and headers, and then, from the end of the
       headers, its body.
     - `SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES` (default `32K`): the largest
-      request line and headers a client may send. Over it, `smallwebwaf` answers
+      request line and headers a client may send. Over it, Go's HTTP server
-      `431` and closes the connection, and nothing reaches the app. It must be
+      answers `431` and closes the connection, and nothing reaches the app. It
-      more than `4K`, and cannot be `off`: Go's HTTP server always has such a
+      must be more than `4K`, and cannot be `off`: Go's HTTP server always has
-      limit, and reads 4 KiB past the one it is given before it refuses.
+      such a limit, and reads 4 KiB past the one it is given before it refuses.
     - `SWWAF_CLIENT_IDLE_TIMEOUT` (default `120s`): how long a kept-open
       connection may wait for its next request before `smallwebwaf` closes it.
       It is longer than the 90 seconds after which traefik, by default, closes a
@@ -435,12 +435,13 @@ The settings, by group:
       the client sends it and the app receives it.
     - `SWWAF_RESPONSE_MAX_BYTES` (default `5G`): the largest response body, as
       the app sends it and the client receives it.
-    - When a limit is passed before the response has started, `smallwebwaf`
+    - When a limit is passed after a request's line and headers have been read,
-      answers itself: `413` for a request body that is too large, `408` for a
+      but before the response has started, `smallwebwaf` answers itself: `413`
-      client that is too slow, `502` for a response that is too large, `504` for
+      for a request body that is too large, `408` for a client too slow to send
-      an app that is too slow. A request that announces a body larger than its
+      its body, `502` for a response that is too large, `504` for an app that is
-      limit is refused before anything reaches the app. Once the response has
+      too slow. A request that announces a body larger than its limit is refused
-      started it can only be cut off, and the connection is closed.
+      before anything reaches the app. Once the response has started it can only
+      be cut off, and the connection is closed.
     - Since a request body streams through, each side can hold up the other: a
       slow client slows the send to the app, and an app slow to take the body
       slows the client's send. So while a request body is still on its way, a
@@ -450,10 +451,11 @@ The settings, by group:
       waiting for the app to take what it had.
     - Go's HTTP server, on which `smallwebwaf` is built, reads a request's line
       and headers before `smallwebwaf` sees the request. A client that takes
-      longer than `SWWAF_CLIENT_REQUEST_TIMEOUT` to send them gets no answer:
+      longer than `SWWAF_CLIENT_REQUEST_TIMEOUT` to send them gets either no
-      the server closes its connection. Headers over
+      answer or an error answer from the server, mostly `400 Bad Request`;
-      `SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES` are answered `431` by the server
+      either way the server closes its connection and nothing reaches the app.
-      itself. Neither request gets a line in the request log.
+      Headers over `SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES` are answered `431` by
+      the server itself. Neither request gets a line in the request log.
     - A WebSocket connection leaves these limits behind once it is upgraded: it
       stays open until either side closes it.
 - Lookup of AS number and country (R7). On by default through GeoJS, which needs
@@ -1324,9 +1326,16 @@ The two processes:
 - A `smallwebwaf` that stops at start, for example on invalid configuration, is
   started again every second and stops again, logging its message each time,
   until the cause is fixed. The health check fails meanwhile.
-- `docker stop` sends SIGTERM to `runsvinit`, which has runit stop both
+- `docker stop` sends SIGTERM to `runsvinit`, which has runit stop both services
-  services, each with SIGTERM, and exits once they have stopped. `smallwebwaf`
+  at once, each with SIGTERM, and exits once they have stopped. `smallwebwaf`
-  writes its state files as it stops (see "Persistent state").
+  stops taking requests, gives those in progress five seconds to finish, and
+  writes its state files as it stops (see "Persistent state"). The requests in
+  progress can finish only while the app still answers. An app that exits at
+  once on SIGTERM ends them: the client gets `502`, or a response cut short if
+  the app had already begun to answer. An app that should let them finish keeps
+  taking and answering requests, not only the ones it already has, for the whole
+  five seconds after SIGTERM, since `smallwebwaf` can still pass it requests it
+  took before then.
 - The container's root filesystem stays writable: runit writes each service's
   status into its directory under `/etc/service`.
 

internal/proxy/bodies.go

@@ -1,8 +1,10 @@
 package proxy
 
 import (
+	"bufio"
 	"errors"
 	"io"
+	"net"
 	"net/http"
 	"sync/atomic"
 
@@ -211,9 +213,20 @@ func (w *responseWriter) FlushError() error {
 	return err
 }
 
+// Hijack takes over the connection to the client, which ReverseProxy does
+// only to pass on the app's 101 Switching Protocols: that is then the
+// status sent.
+func (w *responseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	conn, buffered, err := http.NewResponseController(w.ResponseWriter).Hijack()
+	if err == nil {
+		w.status = http.StatusSwitchingProtocols
+	}
+
+	return conn, buffered, err
+}
+
 // Unwrap lets http.ResponseController reach net/http's own
-// ResponseWriter, which is how ReverseProxy takes over the connection of
+// ResponseWriter for what responseWriter does not do itself.
-// an upgraded request.
 func (w *responseWriter) Unwrap() http.ResponseWriter {
 	return w.ResponseWriter
 }

internal/proxy/coreruleset.go

@@ -23,7 +23,7 @@ import (
 // limit while the Core Rule Set reads it, which it notes nothing of.
 func (rq *request) checkCoreRuleSet() string {
 	cfg := rq.h.config
-	if cfg.WAFMode == config.WAFModeOff || pathExempt(rq.in.URL, cfg.WAFExemptPaths) {
+	if cfg.WAFMode == config.WAFModeOff || pathExempt(rq.in, cfg.WAFExemptPaths) {
 		return ""
 	}
 

internal/proxy/passthrough_test.go

@@ -74,6 +74,47 @@ func TestPassesRequestAndAnswerUnchanged(t *testing.T) {
 	wantRequestFields(t, line, addr, len(requestBody), len(answerBody))
 }
 
+func TestPassesThePathAsSent(t *testing.T) {
+	t.Parallel()
+
+	for _, path := range []string{
+		// An encoded slash and a character Go escapes: |, ^, and é sent
+		// as its UTF-8 bytes.
+		"/a%2Fb|c", "/feat%2Fx/file^1", "/x%2Fy/café",
+		// A path starting with //, which Go would send as a scheme and
+		// host if it were put in URL.Opaque.
+		"//a%2Fb",
+	} {
+		t.Run(path, func(t *testing.T) {
+			t.Parallel()
+
+			saw := make(chan string, 1)
+			app := startApp(t, func(_ http.ResponseWriter, r *http.Request) {
+				saw <- r.RequestURI
+			})
+			addr, out := startProxy(t, app.URL, nil)
+
+			conn := dial(t, addr)
+			send(t, conn, "GET "+path+"?q=1 HTTP/1.1\r\nHost: "+appHost+"\r\n\r\n")
+
+			got := readResponse(t, conn)
+			if got.status != http.StatusOK {
+				t.Fatalf("status %d, want %d", got.status, http.StatusOK)
+			}
+
+			target := <-saw
+			if target != path+"?q=1" {
+				t.Errorf("app saw %s, want %s", target, path+"?q=1")
+			}
+
+			line := out.requestLine(t)
+			if line.Path != path {
+				t.Errorf("log line has path %s, want %s", line.Path, path)
+			}
+		})
+	}
+}
+
 // wantAppSaw checks that the app received the test's request unchanged.
 func wantAppSaw(t *testing.T, saw appSaw, body []byte) {
 	t.Helper()
@@ -309,6 +350,23 @@ func echoAfterUpgrade(w http.ResponseWriter, r *http.Request) {
 	}
 }
 
+func TestAnswers502WhenTheAppSwitchesToAnotherProtocol(t *testing.T) {
+	t.Parallel()
+
+	// answerAfterUpgrade switches to websocket whatever the client asked
+	// for, and ReverseProxy passes on a switch only to the protocol the
+	// client asked for, here "websocket, foo".
+	app := startApp(t, answerAfterUpgrade)
+	addr, out := startProxy(t, app.URL, nil)
+
+	conn := dial(t, addr)
+	send(t, conn, "GET /ws HTTP/1.1\r\nHost: app\r\n"+
+		"Connection: Upgrade\r\nUpgrade: websocket, foo\r\n\r\n")
+
+	wantStatus(t, readResponse(t, conn), http.StatusBadGateway)
+	wantLine(t, out.requestLine(t), http.StatusBadGateway, requestlog.ActionUpstreamError)
+}
+
 func TestServerHasTheDefaultLimits(t *testing.T) {
 	t.Parallel()
 

internal/proxy/ratelimits_test.go

@@ -185,6 +185,9 @@ func TestRateLimitCountsPathsThatAreNotExempt(t *testing.T) {
 		"/assets/x%2Fy",
 		"/assets/x%2fy",
 		`/assets/x\y`,
+		// The same with a character Go escapes, |, for which Go's
+		// URL.EscapedPath gives /assets/x/y%7Cz, with no encoded slash.
+		"/assets/x%2Fy|z",
 	} {
 		t.Run(sent, func(t *testing.T) {
 			t.Parallel()

internal/proxy/request.go

@@ -8,7 +8,6 @@ import (
 	"net/http/httptrace"
 	"net/http/httputil"
 	"net/netip"
-	"net/url"
 	"os"
 	"slices"
 	"strings"
@@ -22,6 +21,7 @@ import (
 	"sneak.berlin/go/smallwebwaf/internal/lookup"
 	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
 	"sneak.berlin/go/smallwebwaf/internal/requestlog"
+	"sneak.berlin/go/smallwebwaf/internal/rules"
 )
 
 // flushAfterEachWrite has ReverseProxy pass on each part of the app's
@@ -137,7 +137,7 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
 			Method:           r.Method,
 			Scheme:           scheme(r, peerTrusted),
 			Host:             r.Host,
-			Path:             r.URL.EscapedPath(),
+			Path:             rules.Path(r),
 			Query:            r.URL.RawQuery,
 			Protocol:         r.Proto,
 			Referer:          r.Referer(),
@@ -284,7 +284,7 @@ func (rq *request) checkClient(ctx context.Context) string {
 	}
 
 	rq.counted = !isInside(rq.client, cfg.RateLimitExemptNets) &&
-		!pathExempt(rq.in.URL, cfg.RateLimitExemptPaths)
+		!pathExempt(rq.in, cfg.RateLimitExemptPaths)
 	if rq.counted {
 		rq.limitPercent, rq.bytesPercent = rq.limitPercentages()
 		rq.line.LimitPercent, rq.line.LimitPercentSetting = rq.limitPercent.logged()
@@ -307,7 +307,7 @@ func (rq *request) checkClient(ctx context.Context) string {
 	return rq.checkCoreRuleSet()
 }
 
-// pathExempt reports whether a request for u is exempt under prefixes,
+// pathExempt reports whether r is exempt under prefixes,
 // SWWAF_RATE_LIMIT_EXEMPT_PATHS or SWWAF_WAF_EXEMPT_PATHS: whether its
 // path as sent, the path the app receives, not percent-decoded, starts
 // with one of prefixes, so that /%61ssets/x is not under /assets/ for an
@@ -316,10 +316,9 @@ func (rq *request) checkClient(ctx context.Context) string {
 // encoded slash (%2F or %2f), never is, since an app may act on it as a
 // path outside every prefix: /assets/..%2Flogin as /login, or /assets%2Fx
 // as one path segment, as Go's router does.
-func pathExempt(u *url.URL, prefixes []string) bool {
+func pathExempt(r *http.Request, prefixes []string) bool {
-	decoded := u.Path
+	decoded := r.URL.Path
-	// EscapedPath is the path as the app receives it, not decoded.
+	sent := rules.Path(r)
-	sent := u.EscapedPath()
 
 	if strings.Contains(decoded, "..") || strings.Contains(decoded, `\`) ||
 		strings.Contains(strings.ToLower(sent), "%2f") {
@@ -375,6 +374,17 @@ func (rq *request) rewrite(pr *httputil.ProxyRequest) {
 	// ReverseProxy drops query parameters it cannot parse; the app gets
 	// the query as the client sent it.
 	pr.Out.URL.RawQuery = pr.In.URL.RawQuery
+	// ReverseProxy sends the path URL.EscapedPath gives, which, for a path
+	// holding a character Go escapes, such as |, is the whole path decoded
+	// and escaped again, %2F turned into /. Opaque is sent as it is, so the
+	// app gets the path as the client sent it. Left out are a target that
+	// is no path, such as *, and a path starting with //, which Go would
+	// send in Opaque as a scheme and host.
+	path := rules.Path(pr.In)
+	if strings.HasPrefix(path, "/") && !strings.HasPrefix(path, "//") {
+		pr.Out.URL.Opaque = path
+	}
+
 	setForwardedHeaders(pr.In, pr.Out, rq.peer, rq.peerTrusted)
 	pr.Out.Header.Set(requestIDHeader, rq.line.RequestID)
 	pr.Out.Header.Del(asnHeader)
@@ -395,8 +405,10 @@ func (rq *request) modifyResponse(res *http.Response) error {
 		// timeouts. ReverseProxy writes this answer straight to the
 		// connection it takes over, not through rq.out, and then copies
 		// what passes each way through res.Body, the connection to the app.
+		// It may still refuse the switch, as when the app's Upgrade is not
+		// the client's, so the status is noted only once it has taken over
+		// the connection, by rq.out's Hijack.
 		rq.stopTimers()
-		rq.out.status = res.StatusCode
 		rq.line.Websocket = true
 
 		conn, ok := res.Body.(io.ReadWriteCloser)
@@ -428,6 +440,13 @@ func (rq *request) modifyResponse(res *http.Response) error {
 // answerError is ReverseProxy's ErrorHandler: the request could not be
 // passed to the app, or the app's answer cannot be passed on.
 func (rq *request) answerError(_ http.ResponseWriter, _ *http.Request, err error) {
+	if rq.upgraded != nil {
+		// The app switched protocols, but the switch was not passed on,
+		// and ReverseProxy leaves the app's connection open when it
+		// refuses it.
+		_ = rq.upgraded.Close()
+	}
+
 	refused := rq.refused.Load()
 	if refused == nil {
 		if rq.in.Context().Err() != nil {
@@ -710,6 +729,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,97 @@ 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 answers without reading the rest of the body, and
+			// says it closes the connection, only once smallwebwaf waits
+			// for the client to send more: it takes the bytes the client
+			// sent, and then waits half the timeout, far longer than
+			// smallwebwaf takes to go on to wait.
+			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")))
+
+				time.Sleep(shortTimeout / 2)
+
+				_, _ = 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()