servewaf answers rproxy's question about each request and takes its report (closes #170)

`smallwebwaf servewaf` runs today's checks on the visitor's request a
question carries and answers allow, deny or close, instead of passing it
to an app. rproxy's report then counts the bytes toward the byte limits
and adds the request to the client's history. SPEC.md gives the exact
question, answer and report, which rproxy follows. `smallwebwaf` with no
command is unchanged.

Judgement call: a third disposition, close, since closing the question's
connection would read as servewaf down and let the request through.
Judgement call: allow can answer a new request id, since a visitor behind
a trusted proxy can choose its own.

Model: opus-5-5

SPEC.md

@@ -1019,8 +1019,8 @@ This section is the agreement between the two. The header names, the fields and
 the statuses below are exact. Each `SWWAF_` setting and check keeps the meaning
 this document gives it, except as this section says.
 
-`servewaf` starts as `smallwebwaf` with no command does. It reads the settings,
-the rule files, the lookup database and the state files, and listens at
+It starts as `smallwebwaf` with no command does. It reads the settings, the rule
+files, the lookup database and the state files, and listens at
 `SWWAF_LISTEN_ADDR`. It stops in the same orderly way, writing the state files.
 `docs/settings.md` lists the settings it ignores.
 
@@ -1048,42 +1048,12 @@ no other header:
   line's `peer_ip`.
 - `X-Smallwebwaf-Content-Length`: the body length the visitor announced. It is
   absent when the visitor announced none.
-- `X-Request-ID`: the request's id, which `rproxy` makes fresh for every request
-  when it arrives. `servewaf` takes it as given and never makes one.
+- `X-Request-ID`: the request's id.
 - `X-Forwarded-Proto`: the scheme.
 
 Before any check, `servewaf` removes the three `X-Smallwebwaf-` headers. It also
 sets `Content-Length` to the length the visitor announced, or removes it. So the
-rule files and the Core Rule Set see the headers the visitor sent, with
-`rproxy`'s `X-Request-ID` and `X-Forwarded-Proto`.
-
-`servewaf` refuses a question with `400` when:
-
-- `X-Smallwebwaf-Client` is not an address, or is an address with a zone, such
-  as `2001:db8::1%eth0`;
-- `X-Request-ID` is absent, empty, over 128 bytes or not valid UTF-8;
-- `X-Request-ID` is the id of a question `servewaf` is still handling, or of a
-  request it holds (see "The report");
-- the body is over 64 KiB.
-
-For a refused question, `servewaf` writes a process warning. It runs no check,
-writes no request log line and counts nothing in the metrics.
-
-These do not refuse a question:
-
-- `X-Smallwebwaf-Peer` absent or not an address: the log line's `peer_ip` is
-  `invalid IP`.
-- `X-Smallwebwaf-Content-Length` not a whole number, or negative: it counts as
-  absent.
-- `X-Forwarded-Proto` absent: the log line's `scheme` is `http`.
-- One of the five headers above sent more than once: `servewaf` uses its first
-  value.
-
-`servewaf` reads the whole body before any check. A question whose body stops
-arriving gets no answer. `servewaf` closes the connection once the 60 seconds
-below run out, or as soon as `rproxy` closes its side. It writes a process
-warning, runs no check, writes no request log line and counts nothing in the
-metrics.
+rule files and the Core Rule Set see the headers the visitor sent.
 
 ### The answer
 
@@ -1091,9 +1061,12 @@ metrics.
 Every answer but the last below carries `X-Smallwebwaf-Disposition`.
 
 - `X-Smallwebwaf-Disposition: allow`, status `200`, no body. `rproxy` passes the
-  request to the app. With `SWWAF_ADD_LOOKUP_HEADERS` the answer also carries
-  `X-Client-ASN` and `X-Client-Country`, which `rproxy` adds to the request it
-  passes on. A header whose value is unknown is left out.
+  request to the app. The answer also carries:
+    - `X-Request-ID`: the id `rproxy` passes to the app, logs and names in the
+      report;
+    - `X-Client-ASN` and `X-Client-Country`, with `SWWAF_ADD_LOOKUP_HEADERS`,
+      which `rproxy` adds to the request it passes on. A header whose value is
+      unknown is left out.
 - `X-Smallwebwaf-Disposition: deny`, with the status, headers and body the
   visitor is to get. `rproxy` gives them to the visitor, less this header. The
   status is one of:
@@ -1104,81 +1077,58 @@ Every answer but the last below carries `X-Smallwebwaf-Disposition`.
 - `X-Smallwebwaf-Disposition: close`, status `200`, no body. This takes the
   place of a refusal while `SWWAF_BAN_RESPONSE` is `close`. `rproxy` closes the
   visitor's connection without an answer.
-- No such header, status `400`, for a question `servewaf` refuses. `rproxy`
-  treats this answer as it treats no answer at all.
+- No such header, status `400`, when `X-Smallwebwaf-Client` is not an address.
+  `rproxy` treats this answer as it treats no answer at all.
+
+The `X-Request-ID` of an `allow` is the question's id, unless `servewaf` has to
+make a new one. A visitor behind a trusted proxy can choose its id, so it makes
+a new one when the question's id is:
+
+- absent;
+- the id of another request awaiting its report;
+- not valid UTF-8, which a JSON report cannot carry.
 
 In `observe` mode a request that `enforce` mode would refuse is answered
 `allow`, and its log line has `would_action`. A path under `/_smallwebwaf/` is
 still answered `404`.
 
-The Core Rule Set inspects the body a question carries only while
-`SWWAF_WAF_BODY_LIMIT` is set. It inspects at most 64 KiB less one byte. So it
-does not inspect a JSON or XML body of 64 KiB or more, which may have been cut
-short.
+The Core Rule Set reads the body a question carries only while
+`SWWAF_WAF_BODY_LIMIT` is set. It reads at most 64 KiB less one byte. So it does
+not read a JSON or XML body of 64 KiB or more, which may have been cut short.
 
 ### The report
 
 Once the visitor's answer has ended, `rproxy` sends `POST /_smallwebwaf/report`
-for each request `servewaf` answered with `allow`, `deny` or `close`. It sends
-none after a `400` or no answer. The report carries no `X-Smallwebwaf-Client`.
-Its body is one JSON object with all of these fields, named as the request log's
-fields of the same meaning:
+for each request it passed to the app on an `allow`. The report carries no
+`X-Smallwebwaf-Client`. Its body is a JSON object with these fields, named as
+the request log's fields of the same meaning:
 
-- `request_id`: the question's `X-Request-ID`;
-- `status`: what the visitor got, `0` if nothing, otherwise from `100` to `599`;
+- `request_id`: the `X-Request-ID` of the `allow`;
+- `status`: what the visitor got, `0` if nothing;
 - `request_bytes` and `response_bytes`: the body bytes each way, with what a
-  WebSocket carried each way, each a whole number from `0` to `1125899906842624`
-  (1 PiB);
+  WebSocket carried each way;
 - `duration_total`: milliseconds from the request's headers being read to the
-  end of the answer, from `0` to `1000000000000` (about 31 years);
+  end of the answer;
 - `duration_upstream_total`: milliseconds from the hand-over to the app to the
-  end of the answer, in the same range, and `0` for a request not passed to the
-  app.
+  end of the answer.
 
-`servewaf` answers `400` and writes a process warning when the body:
+`servewaf` answers `204`, also for a request it does not hold, which it ignores.
+It answers `400` to a body that is not such an object, has a negative byte
+count, or is over 1 MiB. `rproxy` does not act on the answer.
 
-- is not one JSON object, such as `null`, or an object followed by other data;
-- lacks one of these fields, or gives it as `null`;
-- gives a value of the wrong type, or out of its range;
-- is over 1 MiB.
-
-It answers `204` to any other report, also for a request it does not hold, which
-it ignores. It ignores a field not listed here. `rproxy` does not act on the
-answer.
-
-For a request it holds, `servewaf` writes the request's last log line (see "The
-log"). For a request it allowed, it first:
+For a request it holds, `servewaf` then:
 
 - counts the bytes as `SWWAF_BYTES_COUNT` says, toward the client's byte limits
   at the percentages it gave that request;
-- bans a client that passes a byte limit;
-- adds the request with its status to the client's history, the anomaly counters
-  and the metrics.
+- bans a client that passes a byte limit, and writes a process message naming
+  the request, since the request's log line has gone out;
+- adds the request with its status to the client's history and the anomaly
+  counters.
 
-A denied request's counting is finished at its decision, so its report counts
-nothing.
-
-`servewaf` holds each answered request until its report comes, up to 10,000
-requests. Past that, the request answered longest ago is dropped. A request
-whose report never comes gets no last log line. If it was allowed, it is in
-neither the client's history nor the metrics, and its bytes are not counted.
-
-`servewaf` holds only the decision's log line and what counting needs. It never
-holds the request or response objects, and no `Authorization` or `Cookie`. A
-report reaches only what is held, so it can never reach a question still being
-handled. `servewaf` ignores a report naming such a question.
-
-### The log
-
-Each request gets three request log lines, joined by `request_id`:
-
-- `rproxy`'s short line;
-- `servewaf`'s line at its decision;
-- `servewaf`'s line when the report comes, with everything known: the decision
-  line's fields and the report's together.
-
-The repetition is intended. The field `servewaf_line` says which of `servewaf`'s
-two lines a line is. `docs/request-log.md` gives the fields.
+`servewaf` holds each allowed request until its report comes, up to 10,000
+requests. Past that, the request asked about longest ago is dropped. A request
+whose report never comes is in neither the client's history nor the metrics, and
+its bytes are not counted. A denied request is finished at its decision.
 
 ### `servewaf`'s own endpoints
 
@@ -1205,7 +1155,8 @@ asks it. A client banned through one site is refused on all of them, and its
 requests on all of them count toward one set of limits. Log lines, alerts raised
 by a request and ban notes name the site by its host.
 
-`docs/metrics.md` says how its metrics count.
+`docs/request-log.md` gives `servewaf`'s log line, and `docs/metrics.md` how its
+metrics count.
 
 ## Deployment
 

docs/metrics.md

@@ -6,12 +6,8 @@ label as `exported_instance` unless the scrape sets `honor_labels: true`.
 
 `smallwebwaf servewaf` counts a denied request at its decision. It counts an
 allowed request when its report comes, with the status, bytes and times the
-report gives. These are not counted:
-
-- a report itself;
-- an allowed request whose report never comes;
-- a question refused with `400`;
-- a question whose body stopped arriving.
+report gives. A report itself is not counted, and neither is a request whose
+report never comes.
 
 ## Traffic
 

docs/request-log.md

@@ -118,34 +118,19 @@ All in milliseconds:
 - `duration_upstream_first_byte`: until the first byte of the answer;
 - `duration_upstream_total`: until the end of the answer.
 
-## `servewaf`'s lines
+## `servewaf`'s line
 
-`smallwebwaf servewaf` writes two lines for each question it answers, joined by
-`request_id`. The field `servewaf_line` says which of the two a line is:
-
-- `decision`: the line it writes once it has answered the question;
-- `report`: the line it writes when `rproxy`'s report comes, with everything
-  known. The repetition is intended.
-
-A request to its own endpoints writes one line, without `servewaf_line`. A
-report writes no line but the `report` line of the request it names.
-
-These questions write no line:
-
-- a question refused with `400` (see "The question" under "`servewaf`" in
-  [`SPEC.md`](../SPEC.md));
-- a question whose body stopped arriving, which gets no answer.
-
-### The `decision` line
-
-It has the fields above, with these meanings where they differ:
+`smallwebwaf servewaf` writes one line for each question, once it has answered
+it, and one for each request to its own endpoints but a report. A report writes
+no line. A question's line has the fields above, with these meanings where they
+differ:
 
 - `client_ip`: `X-Smallwebwaf-Client`.
 - `peer_ip`: `X-Smallwebwaf-Peer`.
 - `host`: the site the visitor asked for.
 - `protocol`: the question's own, `HTTP/1.1`.
 - `content_length`: `X-Smallwebwaf-Content-Length`.
-- `request_id`: the question's `X-Request-ID`.
+- `request_id`: the id `servewaf` answers with on `allow`.
 - `status`: what `servewaf` answered: `200` for `allow`, the status of `deny`,
   or `0` for `close`, as the visitor is then sent nothing.
 - `request_bytes`: how much of the question's body the Core Rule Set read.
@@ -157,25 +142,11 @@ It has the fields above, with these meanings where they differ:
 
 The line leaves out `upstream_status`, `websocket` and the
 `duration_upstream_...` fields, since `servewaf` passes nothing to the app.
+`rproxy` holds the visitor's status, the body bytes and the times of the app's
+answer. The request id joins the two.
 
-The bytes of an allowed request are counted when its report comes. So `counts`
-holds the client's bytes without this request's.
-
-### The `report` line
-
-It has every field of the `decision` line, and `time` stays when the request
-arrived. These fields say what the report says:
-
-- `status`: what the visitor got, `0` if nothing;
-- `request_bytes` and `response_bytes`: the body bytes each way, with what a
-  WebSocket carried each way;
-- `duration_total`: from the request's headers being read by `rproxy` to the end
-  of the answer;
-- `duration_upstream_total`: from the hand-over to the app to the end of the
-  answer, for an allowed request.
-
-For an allowed request, the report's counting also changes these fields:
-
-- `counts`: the byte totals now include this request's;
-- `limit_hit`, `offence` and `ban_expires`: set when the report's bytes broke a
-  byte limit.
+The bytes of an allowed request are counted when its report comes, after its
+line. So `counts` holds the client's bytes without this request's. A report that
+breaks a byte limit writes a process message instead of `limit_hit` on the line:
+`a report's bytes broke a byte limit`, with `request_id`, `client_ip`, `host`,
+`limit_hit` and `ban_expires`.

docs/settings.md

@@ -345,4 +345,4 @@ A few limits are fixed rather than settings:
 - at most 1,000 DNS blocklist queries are under way at once;
 - at most 20,000 anomaly counters are kept;
 - each alert destination's queue holds at most 1,000 alerts;
-- `servewaf` holds at most 10,000 answered requests awaiting their reports.
+- `servewaf` holds at most 10,000 allowed requests awaiting their reports.

internal/proxy/anomaly_internal_test.go

@@ -15,11 +15,9 @@ func TestWithEveryAnomalyThresholdOffARequestIsNotCounted(t *testing.T) {
 	// anomaly counters, nor a clock, and the request no response: reading
 	// any of them to count the request panics.
 	rq := &request{
-		decision: decision{
-			client:   netip.MustParseAddr("203.0.113.9"),
-			lookedUp: true,
-		},
-		h: &handler{config: &config.Config{LookupSource: "geojs"}},
+		h:        &handler{config: &config.Config{LookupSource: "geojs"}},
+		client:   netip.MustParseAddr("203.0.113.9"),
+		lookedUp: true,
 	}
 
 	defer func() {

internal/proxy/bans.go

@@ -340,11 +340,11 @@ func (rq *request) alertBan(ban bans.Ban) {
 func (rq *request) noted(now time.Time, status int) bans.Request {
 	return bans.Request{
 		Time:      now,
-		Method:    rq.line.Method,
-		Host:      rq.line.Host,
-		Path:      rq.requestURI,
+		Method:    rq.in.Method,
+		Host:      rq.in.Host,
+		Path:      rq.in.URL.RequestURI(),
 		Status:    status,
-		UserAgent: rq.line.UserAgent,
+		UserAgent: rq.in.UserAgent(),
 	}
 }
 

internal/proxy/proxy.go

@@ -1,8 +1,8 @@
-// Package proxy runs the checks on each request and writes its request log
-// line. New passes each request it lets through to the app and the app's
-// answer back, unchanged, within the size and time limits. NewServeWAF instead
-// answers rproxy's question about each request, and takes rproxy's report once
-// the visitor's answer has ended, which writes the request a second log line.
+// Package proxy runs the checks on each request and writes one request log
+// line for it. New passes each request it lets through to the app and the
+// app's answer back, unchanged, within the size and time limits. NewServeWAF
+// instead answers rproxy's question about each request, and takes rproxy's
+// report once the visitor's answer has ended.
 package proxy
 
 import (
@@ -56,8 +56,7 @@ const ClientsPath = "/_smallwebwaf/clients/"
 // Params are what New needs.
 type Params struct {
 	Config *config.Config
-	// RequestLog receives one JSON line per request, and from servewaf a second
-	// when the request's report comes.
+	// RequestLog receives one JSON line per request.
 	RequestLog io.Writer
 	// ProcessLog receives the process's own messages.
 	ProcessLog *slog.Logger
@@ -273,10 +272,9 @@ type handler struct {
 	rules       *rules.Files
 	coreRuleSet *waf.CoreRuleSet
 	alerts      *alerts.Queue
-	// awaitingReport holds, in servewaf, the decision on each answered
-	// question by its id until its report comes, and nil for a question still
-	// being handled.
-	awaitingReport *lru.Cache[string, *decision]
+	// awaitingReport holds, in servewaf, each allowed request by its id
+	// until its report comes.
+	awaitingReport *lru.Cache[string, *request]
 }
 
 // newTransport returns what carries requests to the app. It never goes

internal/proxy/request.go

@@ -39,15 +39,20 @@ type refusal struct {
 	limit  string
 }
 
-// decision is what the checks note of a request: its log line, and what
-// counting the request needs once it has ended. servewaf keeps a copy of it
-// until the request's report comes. It holds no credentials, since the log line
-// never does, and neither the request's objects nor their bodies.
-type decision struct {
-	line   requestlog.Line
-	client netip.Addr
-	// requestURI is the path with the query, as a ban's notes keep it.
-	requestURI string
+// request is one request on its way through smallwebwaf, from the moment
+// its headers have been read to its log line.
+type request struct {
+	h  *handler
+	in *http.Request
+	// rc sets the deadlines of the connection to the client.
+	rc   *http.ResponseController
+	out  *responseWriter
+	body *requestBody // nil for a request without a body
+	line requestlog.Line
+
+	client      netip.Addr
+	peer        netip.Addr
+	peerTrusted bool
 	// site is, in servewaf, the host the visitor asked for, which the
 	// alerts name, since one servewaf serves many sites. It is "" otherwise.
 	site string
@@ -65,37 +70,18 @@ type decision struct {
 	counted                    bool
 	limitPercent, bytesPercent percentage
 	// attack is true for a request that matched a ban rule or asked for a
-	// trap path, ruleBlocked for one a block rule refused, and wafBlocked for
-	// one the Core Rule Set refused, each an offence its client's history
-	// counts.
-	attack, ruleBlocked, wafBlocked bool
-	// reputation is the reputation sources that list the client, for the
-	// notes of a ban the request makes.
-	reputation []bans.ReputationHit
-}
-
-// request is one request on its way through smallwebwaf, from the moment
-// its headers have been read to its log line.
-type request struct {
-	decision
-
-	h  *handler
-	in *http.Request
-	// rc sets the deadlines of the connection to the client.
-	rc   *http.ResponseController
-	out  *responseWriter
-	body *requestBody // nil for a request without a body
-
-	peer        netip.Addr
-	peerTrusted bool
-	// tokenRefused is true for a request refused for a missing or wrong
-	// token, an offence its client's history counts.
-	tokenRefused bool
+	// trap path, ruleBlocked for one a block rule refused, wafBlocked for
+	// one the Core Rule Set refused, and tokenRefused for one refused for a
+	// missing or wrong token, each an offence its client's history counts.
+	attack, ruleBlocked, wafBlocked, tokenRefused bool
 	// blocklisted is true once a blocklist is found to list the client,
 	// dnsblListed once a DNSBL zone's verdict is, and abuseIPDBHit once
 	// AbuseIPDB's score of it is a hit.
 	blocklisted, dnsblListed, abuseIPDBHit bool
-	start                                  time.Time
+	// reputation is the reputation sources that list the client, for the
+	// notes of a ban the request makes.
+	reputation []bans.ReputationHit
+	start      time.Time
 	// checked is when the checks were done, and upstreamStart when the
 	// request was handed to the app.
 	checked       time.Time
@@ -150,39 +136,36 @@ func (h *handler) startRequest(
 	forwardedFor := r.Header.Values("X-Forwarded-For")
 
 	rq := &request{
-		decision: decision{
-			client:     client,
-			requestURI: r.URL.RequestURI(),
-			line: requestlog.Line{
-				Time:             requestlog.FormatTime(start),
-				Instance:         h.config.InstanceName,
-				ClientIP:         client.String(),
-				Method:           r.Method,
-				Scheme:           scheme(r, peerTrusted),
-				Host:             r.Host,
-				Path:             rules.Path(r),
-				Query:            r.URL.RawQuery,
-				Protocol:         r.Proto,
-				Referer:          r.Referer(),
-				UserAgent:        r.UserAgent(),
-				RequestID:        requestID(r, peerTrusted),
-				PeerIP:           peer.String(),
-				ForwardedFor:     strings.Join(forwardedFor, ", "),
-				ClientGroup:      h.clientGroup(client).String(),
-				ContentType:      r.Header.Get("Content-Type"),
-				RequestHeaders:   requestHeaders(r, h.config.LogRequestHeaders),
-				HasAuthorization: len(r.Header.Values("Authorization")) > 0,
-				HasCookie:        len(r.Header.Values("Cookie")) > 0,
-				Action:           requestlog.ActionForward,
-			},
-		},
 		h:           h,
 		in:          r,
 		rc:          http.NewResponseController(w),
 		out:         &responseWriter{ResponseWriter: w},
+		client:      client,
 		peer:        peer,
 		peerTrusted: peerTrusted,
 		start:       start,
+		line: requestlog.Line{
+			Time:             requestlog.FormatTime(start),
+			Instance:         h.config.InstanceName,
+			ClientIP:         client.String(),
+			Method:           r.Method,
+			Scheme:           scheme(r, peerTrusted),
+			Host:             r.Host,
+			Path:             rules.Path(r),
+			Query:            r.URL.RawQuery,
+			Protocol:         r.Proto,
+			Referer:          r.Referer(),
+			UserAgent:        r.UserAgent(),
+			RequestID:        requestID(r, peerTrusted),
+			PeerIP:           peer.String(),
+			ForwardedFor:     strings.Join(forwardedFor, ", "),
+			ClientGroup:      h.clientGroup(client).String(),
+			ContentType:      r.Header.Get("Content-Type"),
+			RequestHeaders:   requestHeaders(r, h.config.LogRequestHeaders),
+			HasAuthorization: len(r.Header.Values("Authorization")) > 0,
+			HasCookie:        len(r.Header.Values("Cookie")) > 0,
+			Action:           requestlog.ActionForward,
+		},
 	}
 
 	// A length of -1 is a body whose length was not announced.
@@ -608,12 +591,7 @@ func (rq *request) finish() {
 		rq.h.metrics.RequestEnded(line, limit, duration, upstreamDuration)
 	}
 
-	rq.writeLine()
-}
-
-// writeLine writes the request's log line.
-func (rq *request) writeLine() {
-	err := requestlog.Write(rq.h.requestLog, &rq.line)
+	err := requestlog.Write(rq.h.requestLog, line)
 	if err != nil {
 		rq.h.processLog.Error("writing the request log failed", "error", err.Error())
 	}

internal/proxy/servewaf.go

@@ -1,11 +1,8 @@
 package proxy
 
 import (
-	"bytes"
+	"crypto/rand"
 	"encoding/json"
-	"errors"
-	"fmt"
-	"io"
 	"net/http"
 	"net/netip"
 	"strconv"
@@ -46,30 +43,21 @@ const (
 	DispositionClose = "close"
 )
 
-// ReportPath is where rproxy sends the report of each request servewaf
-// answered.
+// ReportPath is where rproxy sends the report of each request it passed to
+// the app.
 const ReportPath = "/_smallwebwaf/report"
 
 // QuestionBodyMaxBytes is the most of a visitor's body a question carries.
 const QuestionBodyMaxBytes = 64 << 10
 
 const (
-	// maxAwaitingReport is the most answered requests held until their
-	// reports come. Past it, the request answered longest ago is dropped.
+	// maxAwaitingReport is the most allowed requests held until their
+	// reports come. Past it, the request asked about longest ago is dropped.
 	maxAwaitingReport = 10000
-	// maxRequestIDBytes is the longest id a question may give.
-	maxRequestIDBytes = 128
 	// reportBodyMaxBytes is the most of a report's body that is read. It is
-	// far above any report's.
+	// far above any report's, since the longest thing in one is the request
+	// id, which comes from a header.
 	reportBodyMaxBytes = 1 << 20
-	// maxHTTPStatus is the highest status a report may give.
-	maxHTTPStatus = 599
-	// maxReportedBytes is the most bytes a report may give for each way, 1
-	// PiB, so that adding them up cannot overflow.
-	maxReportedBytes = 1 << 50
-	// maxReportedMilliseconds is the longest duration a report may give,
-	// about 31 years, so that it fits a time.Duration.
-	maxReportedMilliseconds = 1e12
 	// serveWAFTimeout bounds how long a request to servewaf takes to arrive,
 	// and its answer to leave, and serveWAFIdleTimeout how long a kept-open
 	// connection waits for its next request.
@@ -77,15 +65,10 @@ const (
 	serveWAFIdleTimeout = 120 * time.Second
 )
 
-var (
-	errReportFieldMissing = errors.New("a field is missing")
-	errReportValue        = errors.New("a value is out of range")
-)
-
 // Report is the JSON object rproxy posts to ReportPath once the visitor's
 // answer has ended, its fields named as the request log's of the same
-// meaning. RequestID is the question's id. Status is what the visitor got, 0
-// if nothing. The durations are in milliseconds.
+// meaning. RequestID is the id servewaf's allow gave. Status is what the
+// visitor got, 0 if nothing. The durations are in milliseconds.
 //
 //nolint:tagliatelle // docs/request-log.md names the fields in snake_case
 type Report struct {
@@ -119,7 +102,7 @@ func NewServeWAF(params Params) *Server {
 
 	h := newHandler(params)
 
-	awaitingReport, err := lru.New[string, *decision](maxAwaitingReport)
+	awaitingReport, err := lru.New[string, *request](maxAwaitingReport)
 	if err != nil {
 		panic(err) // New fails only for a size below one
 	}
@@ -147,27 +130,26 @@ func (h *handler) serveWAF(w http.ResponseWriter, r *http.Request) {
 }
 
 // answerQuestion runs the checks on the visitor's request a question
-// carries, and answers rproxy what to do with it. A denied request's counting
-// is finished here, and an allowed one's by its report.
+// carries, and answers rproxy what to do with it. A denied request is
+// finished here. An allowed one is finished by its report. A question
+// without a visitor's address gets no disposition, so that rproxy treats
+// it as it treats no answer.
 func (h *handler) answerQuestion(w http.ResponseWriter, r *http.Request) {
-	client, body, ok := h.readQuestion(w, r)
-	if !ok {
+	client, err := netip.ParseAddr(r.Header.Get(ClientHeader))
+	if err != nil {
+		h.processLog.Warn("a question gives no visitor's address", "error", err.Error())
+		http.Error(w, "X-Smallwebwaf-Client is not an address", http.StatusBadRequest)
+
 		return
 	}
 
 	// One that cannot be read leaves the log line's peer_ip invalid.
 	peer, _ := netip.ParseAddr(r.Header.Get(PeerHeader))
 
-	rq := h.startRequest(w, asTheVisitorSentIt(r, body), client.Unmap(), peer.Unmap(),
-		true)
-	// The last deferred runs first, so that what is held has the finished log
-	// line. Go's server sends the answer only once this function has
-	// returned, so the report cannot come before it is held.
-	defer rq.holdForReport()
+	rq := h.startRequest(w, asTheVisitorSentIt(r), client.Unmap(), peer.Unmap(), true)
 	defer rq.finish()
 
 	rq.site = r.Host
-	rq.line.ServeWAFLine = requestlog.ServeWAFLineDecision
 	refused := rq.check(r.Context())
 	rq.checked = time.Now()
 	underOwnPrefix := strings.HasPrefix(r.URL.Path, adminPrefix)
@@ -199,70 +181,11 @@ func (h *handler) answerQuestion(w http.ResponseWriter, r *http.Request) {
 	http.Error(rq.out, http.StatusText(http.StatusNotFound), http.StatusNotFound)
 }
 
-// readQuestion returns the visitor's address and the body a question carries,
-// and whether servewaf takes the question. It answers a question it does not
-// take with 400 and no disposition, which rproxy treats as it treats no
-// answer. The id of a question it takes is held from here on, without a
-// decision yet, so that another question with that id is refused while this
-// one is being handled.
-//
-// The body is read before any check, since Go's server does not send an answer
-// until it has read the body. A question whose body stops arriving gets no
-// answer, and is not looked at.
-func (h *handler) readQuestion(
-	w http.ResponseWriter, r *http.Request,
-) (netip.Addr, []byte, bool) {
-	client, err := netip.ParseAddr(r.Header.Get(ClientHeader))
-	if err != nil || client.Zone() != "" {
-		h.refuseQuestion(w, ClientHeader+" is not an address without a zone")
-
-		return netip.Addr{}, nil, false
-	}
-
-	id := r.Header.Get(requestIDHeader)
-	if id == "" || len(id) > maxRequestIDBytes || !utf8.ValidString(id) {
-		h.refuseQuestion(w, requestIDHeader+" is not a valid id")
-
-		return netip.Addr{}, nil, false
-	}
-
-	body, err := io.ReadAll(http.MaxBytesReader(w, r.Body, QuestionBodyMaxBytes))
-
-	if _, tooLarge := errors.AsType[*http.MaxBytesError](err); tooLarge {
-		h.refuseQuestion(w, "the body is over 64 KiB")
-
-		return netip.Addr{}, nil, false
-	}
-
-	if err != nil {
-		h.processLog.Warn("a question's body stopped arriving", "error", err.Error())
-		// This panic has Go's server close the connection without an answer,
-		// and log nothing.
-		panic(http.ErrAbortHandler)
-	}
-
-	held, _ := h.awaitingReport.ContainsOrAdd(id, nil)
-	if held {
-		h.refuseQuestion(w, requestIDHeader+" is the id of a request servewaf holds")
-
-		return netip.Addr{}, nil, false
-	}
-
-	return client, body, true
-}
-
-// refuseQuestion answers a question servewaf does not take, for reason.
-func (h *handler) refuseQuestion(w http.ResponseWriter, reason string) {
-	h.processLog.Warn("a question is refused", "reason", reason)
-	http.Error(w, reason, http.StatusBadRequest)
-}
-
 // asTheVisitorSentIt returns a copy of r, a question, as the checks and the
-// log line are to see it: without the headers rproxy adds for servewaf, with
-// body, which has been read of r, and with the length the visitor announced,
-// as -1 when it announced none. The question's own length covers only the part
-// of the body it carries.
-func asTheVisitorSentIt(r *http.Request, body []byte) *http.Request {
+// log line are to see it: without the headers rproxy adds for servewaf, and
+// with the length the visitor announced, as -1 when it announced none. The
+// question's own length covers only the part of the body it carries.
+func asTheVisitorSentIt(r *http.Request) *http.Request {
 	sent := r.Clone(r.Context())
 	announced := sent.Header.Get(ContentLengthHeader)
 
@@ -279,34 +202,55 @@ func asTheVisitorSentIt(r *http.Request, body []byte) *http.Request {
 		sent.Header.Set("Content-Length", announced)
 	}
 
-	sent.Body = http.NoBody
-	if len(body) > 0 {
-		sent.Body = io.NopCloser(bytes.NewReader(body))
-	}
-
 	return sent
 }
 
-// allow answers a question with DispositionAllow and, while
-// SWWAF_ADD_LOOKUP_HEADERS is set, the client's AS number and country.
+// allow answers a question with DispositionAllow, the request's id and,
+// while SWWAF_ADD_LOOKUP_HEADERS is set, the client's AS number and country,
+// and holds the request until its report comes.
 func (rq *request) allow() {
 	rq.allowed = true
 
+	// servewaf sends no app this part of the body, and the table of requests
+	// awaiting their reports must not hold it.
+	if rq.body != nil {
+		rq.body.readByCoreRuleSet = nil
+	}
+
+	rq.awaitReport()
+
 	header := rq.out.Header()
 	header.Set(DispositionHeader, DispositionAllow)
+	header.Set(requestIDHeader, rq.line.RequestID)
 
 	if rq.h.config.AddLookupHeaders {
 		setLookupHeaders(header, rq.line.ASN, rq.line.Country)
 	}
 
+	// Go's server sends this only once the handler has returned, so a report
+	// that answers it cannot come while the handler still uses rq.
 	rq.out.WriteHeader(http.StatusOK)
 }
 
-// holdForReport holds a copy of what the report's steps need, by the request's
-// id. A report only ever reaches that copy, never the request being handled.
-func (rq *request) holdForReport() {
-	held := rq.decision
-	rq.h.awaitingReport.Add(rq.line.RequestID, &held)
+// awaitReport holds the request by its id, which its report is to name. A
+// visitor behind a trusted proxy can choose its id, which must not let it
+// have its report taken for another request's, or lost, and its bytes not
+// counted. So the request gets a new id when another held request has the
+// question's, or when that is not valid UTF-8, which a JSON report cannot
+// carry unchanged.
+func (rq *request) awaitReport() {
+	id := rq.line.RequestID
+	if !utf8.ValidString(id) {
+		id = rand.Text()
+	}
+
+	held, _ := rq.h.awaitingReport.ContainsOrAdd(id, rq)
+	if held {
+		id = rand.Text()
+		rq.h.awaitingReport.Add(id, rq)
+	}
+
+	rq.line.RequestID = id
 }
 
 // deny answers a question with what the visitor is to get for r.
@@ -327,7 +271,7 @@ func (rq *request) deny(r refusal) {
 
 // answerOwnEndpoint answers a request to servewaf's own address. No check
 // runs on it: the address is on the private network, where the peers are
-// rproxy and the admin's tools, not visitors.
+// rproxy and the admin's tools, not visitors. A report writes no log line.
 func (h *handler) answerOwnEndpoint(w http.ResponseWriter, r *http.Request) {
 	if r.Method == http.MethodPost && r.URL.Path == ReportPath {
 		h.takeReport(w, r)
@@ -350,115 +294,57 @@ func (h *handler) answerOwnEndpoint(w http.ResponseWriter, r *http.Request) {
 }
 
 // takeReport answers POST ReportPath: it finishes the request the report
-// names, if it holds that request's decision, and ignores the report
-// otherwise.
+// names, if it holds that request, and ignores the report otherwise.
 func (h *handler) takeReport(w http.ResponseWriter, r *http.Request) {
-	report, err := readReport(w, r)
-	if err != nil {
-		h.processLog.Warn("a report is refused", "error", err.Error())
+	var report Report
+
+	err := json.NewDecoder(http.MaxBytesReader(w, r.Body, reportBodyMaxBytes)).
+		Decode(&report)
+	if err != nil || report.RequestBytes < 0 || report.ResponseBytes < 0 {
 		http.Error(w, "the body is not a report", http.StatusBadRequest)
 
 		return
 	}
 
-	held, found := h.awaitingReport.Peek(report.RequestID)
+	rq, held := h.awaitingReport.Peek(report.RequestID)
 	// Remove reports true to one report only, of several that name the id.
-	if found && held != nil && h.awaitingReport.Remove(report.RequestID) {
-		h.finishWith(held, report)
+	if held && h.awaitingReport.Remove(report.RequestID) {
+		rq.finishWith(report)
 	}
 
 	w.WriteHeader(http.StatusNoContent)
 }
 
-// readReport reads a report from r's body, which must be one JSON object with
-// all of Report's fields, in the ranges SPEC.md gives.
-func readReport(w http.ResponseWriter, r *http.Request) (Report, error) {
-	var report Report
-
-	body, err := io.ReadAll(http.MaxBytesReader(w, r.Body, reportBodyMaxBytes))
-	if err != nil {
-		return report, fmt.Errorf("read the body: %w", err)
-	}
-
-	var fields map[string]json.RawMessage
-
-	err = json.Unmarshal(body, &fields)
-	if err != nil {
-		return report, fmt.Errorf("decode the body: %w", err)
-	}
-
-	for _, name := range []string{
-		"request_id", "status", "request_bytes", "response_bytes",
-		"duration_total", "duration_upstream_total",
-	} {
-		value, there := fields[name]
-		if !there || string(value) == "null" {
-			return report, fmt.Errorf("%w: %s", errReportFieldMissing, name)
-		}
-	}
-
-	err = json.Unmarshal(body, &report)
-	if err != nil {
-		return report, fmt.Errorf("decode the body: %w", err)
-	}
-
-	return report, report.checkRanges()
-}
-
-// checkRanges returns an error for a value of the report that cannot be true.
-func (report *Report) checkRanges() error {
-	switch {
-	case report.Status != 0 &&
-		(report.Status < http.StatusContinue || report.Status > maxHTTPStatus):
-		return fmt.Errorf("%w: status", errReportValue)
-	case report.RequestBytes < 0 || report.RequestBytes > maxReportedBytes:
-		return fmt.Errorf("%w: request_bytes", errReportValue)
-	case report.ResponseBytes < 0 || report.ResponseBytes > maxReportedBytes:
-		return fmt.Errorf("%w: response_bytes", errReportValue)
-	case report.DurationTotal < 0 || report.DurationTotal > maxReportedMilliseconds:
-		return fmt.Errorf("%w: duration_total", errReportValue)
-	case report.DurationUpstreamTotal < 0 ||
-		report.DurationUpstreamTotal > maxReportedMilliseconds:
-		return fmt.Errorf("%w: duration_upstream_total", errReportValue)
-	}
-
-	return nil
-}
-
-// finishWith finishes a request with what its report says, and writes the
-// request's last log line, which holds its decision's fields and the report's.
-// For an allowed request it first takes the steps ServeHTTP takes once a
-// request passed to the app has ended, with the status and bytes of the report
-// in place of those it would have seen. A denied request's counting was
-// finished at its decision.
-func (h *handler) finishWith(held *decision, report Report) {
-	rq := &request{
-		decision: *held,
-		h:        h,
-		out:      &responseWriter{status: report.Status, bytes: report.ResponseBytes},
-		body:     &requestBody{},
-	}
+// finishWith finishes an allowed request with what its report says: the
+// steps ServeHTTP takes once a request passed to the app has ended, with
+// the status and bytes of the report in place of those it would have seen.
+func (rq *request) finishWith(report Report) {
+	// A limit the question broke has been logged.
+	rq.line.LimitHit = ""
+	// addToHistory goes by this for whether the request reached the app.
+	rq.upstreamStart = time.Now()
+	rq.out = &responseWriter{status: report.Status, bytes: report.ResponseBytes}
+	rq.body = &requestBody{}
 	rq.body.bytes.Store(report.RequestBytes)
 
-	rq.line.ServeWAFLine = requestlog.ServeWAFLineReport
+	rq.countBytes()
+	rq.countAnomalies()
+	rq.addToHistory()
+
 	rq.line.Status = report.Status
 	rq.line.RequestBytes = report.RequestBytes
 	rq.line.ResponseBytes = report.ResponseBytes
-	rq.line.DurationTotal = report.DurationTotal
+	rq.h.metrics.RequestReported(&rq.line,
+		time.Duration(report.DurationTotal*float64(time.Millisecond)),
+		time.Duration(report.DurationUpstreamTotal*float64(time.Millisecond)))
 
-	if rq.allowed {
-		rq.line.DurationUpstreamTotal = &report.DurationUpstreamTotal
-		// addToHistory goes by this for whether the request reached the app.
-		rq.upstreamStart = time.Now()
-
-		rq.countBytes()
-		rq.countAnomalies()
-		rq.addToHistory()
-
-		rq.h.metrics.RequestReported(&rq.line,
-			time.Duration(report.DurationTotal*float64(time.Millisecond)),
-			time.Duration(report.DurationUpstreamTotal*float64(time.Millisecond)))
+	// The request's log line went out with the answer to its question.
+	if rq.line.LimitHit != "" {
+		rq.h.processLog.Warn("a report's bytes broke a byte limit",
+			"request_id", rq.line.RequestID,
+			"client_ip", rq.line.ClientIP,
+			"host", rq.line.Host,
+			"limit_hit", rq.line.LimitHit,
+			"ban_expires", rq.line.BanExpires)
 	}
-
-	rq.writeLine()
 }

internal/requestlog/requestlog.go

@@ -1,6 +1,6 @@
 // Package requestlog writes the lines smallwebwaf prints on stdout: one
-// JSON object per request, or two from servewaf, marked "type":"request", and
-// the process's own messages as JSON lines marked "type":"process".
+// JSON object per request, marked "type":"request", and the process's own
+// messages as JSON lines marked "type":"process".
 package requestlog
 
 import (
@@ -60,16 +60,6 @@ const OffenceLimit = "limit"
 // that broke the error burst.
 const LimitHitErrorBurst = "error_burst"
 
-// The servewaf_line a request line names, which says which of servewaf's two
-// lines about a question it is.
-const (
-	// ServeWAFLineDecision is servewaf's line at its decision.
-	ServeWAFLineDecision = "decision"
-	// ServeWAFLineReport is servewaf's line when rproxy's report comes, with
-	// the decision's fields and the report's together.
-	ServeWAFLineReport = "report"
-)
-
 // timeLayout is RFC 3339 with milliseconds.
 const timeLayout = "2006-01-02T15:04:05.000Z07:00"
 
@@ -80,9 +70,6 @@ const timeLayout = "2006-01-02T15:04:05.000Z07:00"
 //nolint:tagliatelle // docs/request-log.md names the fields in snake_case
 type Line struct {
 	Type string `json:"type"`
-	// ServeWAFLine is ServeWAFLineDecision or ServeWAFLineReport on servewaf's
-	// two lines about a question.
-	ServeWAFLine string `json:"servewaf_line,omitempty"`
 
 	// The standard web log fields. Scheme is how the client reached
 	// smallwebwaf, or the trusted proxy in front of it.

internal/smallwebwaf/servewaf_test.go

@@ -2,95 +2,15 @@ package smallwebwaf_test
 
 import (
 	"context"
-	"crypto/rand"
 	"io"
 	"net/http"
-	"os"
-	"os/exec"
 	"path/filepath"
-	"strings"
-	"syscall"
 	"testing"
 	"time"
 
 	"sneak.berlin/go/smallwebwaf/internal/proxy"
-	"sneak.berlin/go/smallwebwaf/internal/smallwebwaf"
 )
 
-// commandForMain, while set in the environment, has this test binary run Main
-// with the command it gives, in place of the tests, so that a test can run
-// Main in a process of its own.
-const commandForMain = "SMALLWEBWAF_TEST_COMMAND"
-
-func TestMain(m *testing.M) {
-	command, set := os.LookupEnv(commandForMain)
-	if !set {
-		os.Exit(m.Run())
-	}
-
-	os.Args = strings.Fields("smallwebwaf " + command)
-
-	os.Exit(smallwebwaf.Main(testVersion))
-}
-
-func TestMainAnswersQuestionsOnlyAsServeWAF(t *testing.T) {
-	t.Parallel()
-
-	for _, tc := range []struct {
-		command, disposition string
-	}{
-		{"servewaf", proxy.DispositionAllow},
-		{"", ""},
-	} {
-		t.Run("command "+tc.command, func(t *testing.T) {
-			t.Parallel()
-
-			binary, err := os.Executable()
-			if err != nil {
-				t.Fatalf("find the test binary: %v", err)
-			}
-
-			ctx, cancel := context.WithTimeout(t.Context(), 3*waitLimit)
-			defer cancel()
-
-			out := &output{}
-			cmd := exec.CommandContext(ctx, binary) //nolint:gosec // this test binary
-			cmd.Stdout = out
-
-			cmd.Env = append(os.Environ(),
-				commandForMain+"="+tc.command,
-				listenAddr+"="+localhost+":0",
-				upstreamURL+"="+startApp(t),
-				stateDir+"="+t.TempDir(),
-				rulesDir+"="+t.TempDir(),
-				lookupSource+"=off")
-
-			err = cmd.Start()
-			if err != nil {
-				t.Fatalf("start: %v", err)
-			}
-
-			t.Cleanup(func() {
-				_ = cmd.Process.Kill()
-				_ = cmd.Wait()
-			})
-
-			addr, _ := out.line(t, "msg", "starting")["address"].(string)
-			ask(t, addr, "/", http.StatusOK, tc.disposition)
-
-			err = cmd.Process.Signal(syscall.SIGTERM)
-			if err != nil {
-				t.Fatalf("signal: %v", err)
-			}
-
-			err = cmd.Wait()
-			if err != nil {
-				t.Errorf("exit: %v; output:\n%s", err, out.text())
-			}
-		})
-	}
-}
-
 // ask sends servewaf at addr rproxy's question about a request for path from
 // placed, checks the answer's status and disposition, and closes it.
 func ask(t *testing.T, addr, path string, status int, disposition string) {
@@ -103,7 +23,6 @@ func ask(t *testing.T, addr, path string, status int, disposition string) {
 	}
 
 	req.Header.Set(proxy.ClientHeader, placed)
-	req.Header.Set("X-Request-ID", rand.Text())
 
 	transport := &http.Transport{}
 	defer transport.CloseIdleConnections()