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 each
question carries, answers rproxy, and passes nothing to an app. rproxy reports
every request servewaf answered. A report counts an allowed request's bytes and
writes servewaf's second log line. The table holds a copy of what a report
needs, never the request, so a report cannot reach a request being handled.

Judgement call: a question's body is read before any check; over 64 KiB gets 400.
Judgement call: a report's bytes and durations have ceilings, so they cannot overflow.
Judgement call: a `close` disposition for SWWAF_BAN_RESPONSE=close.

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.
 
-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
+`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
 `SWWAF_LISTEN_ADDR`. It stops in the same orderly way, writing the state files.
 `docs/settings.md` lists the settings it ignores.
 
@@ -1048,12 +1048,42 @@ 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.
+- `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-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.
+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.
 
 ### The answer
 
@@ -1061,12 +1091,9 @@ rule files and the Core Rule Set see the headers the visitor sent.
 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. 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.
+  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.
 - `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:
@@ -1077,58 +1104,81 @@ 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`, 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.
+- No such header, status `400`, for a question `servewaf` refuses. `rproxy`
+  treats this answer as it treats no answer at all.
 
 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 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 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 report
 
 Once the visitor's answer has ended, `rproxy` sends `POST /_smallwebwaf/report`
-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:
+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:
 
-- `request_id`: the `X-Request-ID` of the `allow`;
-- `status`: what the visitor got, `0` if nothing;
+- `request_id`: the question's `X-Request-ID`;
+- `status`: what the visitor got, `0` if nothing, otherwise from `100` to `599`;
 - `request_bytes` and `response_bytes`: the body bytes each way, with what a
-  WebSocket carried each way;
+  WebSocket carried each way, each a whole number from `0` to `1125899906842624`
+  (1 PiB);
 - `duration_total`: milliseconds from the request's headers being read to the
-  end of the answer;
+  end of the answer, from `0` to `1000000000000` (about 31 years);
 - `duration_upstream_total`: milliseconds from the hand-over to the app to the
-  end of the answer.
+  end of the answer, in the same range, and `0` for a request not passed to the
+  app.
 
-`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.
+`servewaf` answers `400` and writes a process warning when the body:
 
-For a request it holds, `servewaf` then:
+- 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:
 
 - 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, 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.
+- 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.
 
-`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.
+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`'s own endpoints
 
@@ -1155,8 +1205,7 @@ 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/request-log.md` gives `servewaf`'s log line, and `docs/metrics.md` how its
-metrics count.
+`docs/metrics.md` says how its metrics count.
 
 ## Deployment
 

docs/metrics.md

@@ -6,8 +6,12 @@ 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. A report itself is not counted, and neither is a request whose
-report never comes.
+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.
 
 ## Traffic
 

docs/request-log.md

@@ -118,19 +118,34 @@ 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 line
+## `servewaf`'s lines
 
-`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:
+`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:
 
 - `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 id `servewaf` answers with on `allow`.
+- `request_id`: the question's `X-Request-ID`.
 - `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.
@@ -142,11 +157,25 @@ 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, 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`.
+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.

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 allowed requests awaiting their reports.
+- `servewaf` holds at most 10,000 answered requests awaiting their reports.

internal/proxy/anomaly_internal_test.go

@@ -15,9 +15,11 @@ 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{
-		h:        &handler{config: &config.Config{LookupSource: "geojs"}},
-		client:   netip.MustParseAddr("203.0.113.9"),
-		lookedUp: true,
+		decision: decision{
+			client:   netip.MustParseAddr("203.0.113.9"),
+			lookedUp: true,
+		},
+		h: &handler{config: &config.Config{LookupSource: "geojs"}},
 	}
 
 	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.in.Method,
-		Host:      rq.in.Host,
-		Path:      rq.in.URL.RequestURI(),
+		Method:    rq.line.Method,
+		Host:      rq.line.Host,
+		Path:      rq.requestURI,
 		Status:    status,
-		UserAgent: rq.in.UserAgent(),
+		UserAgent: rq.line.UserAgent,
 	}
 }
 

internal/proxy/proxy.go

@@ -1,8 +1,8 @@
-// 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 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
 
 import (
@@ -56,7 +56,8 @@ const ClientsPath = "/_smallwebwaf/clients/"
 // Params are what New needs.
 type Params struct {
 	Config *config.Config
-	// RequestLog receives one JSON line per request.
+	// RequestLog receives one JSON line per request, and from servewaf a second
+	// when the request's report comes.
 	RequestLog io.Writer
 	// ProcessLog receives the process's own messages.
 	ProcessLog *slog.Logger
@@ -272,9 +273,10 @@ type handler struct {
 	rules       *rules.Files
 	coreRuleSet *waf.CoreRuleSet
 	alerts      *alerts.Queue
-	// awaitingReport holds, in servewaf, each allowed request by its id
-	// until its report comes.
-	awaitingReport *lru.Cache[string, *request]
+	// 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]
 }
 
 // newTransport returns what carries requests to the app. It never goes

internal/proxy/request.go

@@ -39,20 +39,15 @@ type refusal struct {
 	limit  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
+// 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
 	// 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
@@ -70,18 +65,37 @@ type request 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, 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
+	// 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
 	// 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
-	// reputation is the reputation sources that list the client, for the
-	// notes of a ban the request makes.
-	reputation []bans.ReputationHit
-	start      time.Time
+	start                                  time.Time
 	// checked is when the checks were done, and upstreamStart when the
 	// request was handed to the app.
 	checked       time.Time
@@ -136,36 +150,39 @@ 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.
@@ -591,7 +608,12 @@ func (rq *request) finish() {
 		rq.h.metrics.RequestEnded(line, limit, duration, upstreamDuration)
 	}
 
-	err := requestlog.Write(rq.h.requestLog, line)
+	rq.writeLine()
+}
+
+// writeLine writes the request's log line.
+func (rq *request) writeLine() {
+	err := requestlog.Write(rq.h.requestLog, &rq.line)
 	if err != nil {
 		rq.h.processLog.Error("writing the request log failed", "error", err.Error())
 	}

internal/proxy/servewaf.go

@@ -1,8 +1,11 @@
 package proxy
 
 import (
-	"crypto/rand"
+	"bytes"
 	"encoding/json"
+	"errors"
+	"fmt"
+	"io"
 	"net/http"
 	"net/netip"
 	"strconv"
@@ -43,21 +46,30 @@ const (
 	DispositionClose = "close"
 )
 
-// ReportPath is where rproxy sends the report of each request it passed to
-// the app.
+// ReportPath is where rproxy sends the report of each request servewaf
+// answered.
 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 allowed requests held until their
-	// reports come. Past it, the request asked about longest ago is dropped.
+	// maxAwaitingReport is the most answered requests held until their
+	// reports come. Past it, the request answered 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, since the longest thing in one is the request
-	// id, which comes from a header.
+	// far above any report's.
 	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.
@@ -65,10 +77,15 @@ 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 id servewaf's allow gave. Status is what the
-// visitor got, 0 if nothing. The durations are in milliseconds.
+// meaning. RequestID is the question's id. 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 {
@@ -102,7 +119,7 @@ func NewServeWAF(params Params) *Server {
 
 	h := newHandler(params)
 
-	awaitingReport, err := lru.New[string, *request](maxAwaitingReport)
+	awaitingReport, err := lru.New[string, *decision](maxAwaitingReport)
 	if err != nil {
 		panic(err) // New fails only for a size below one
 	}
@@ -130,26 +147,27 @@ 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 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.
+// 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.
 func (h *handler) answerQuestion(w http.ResponseWriter, r *http.Request) {
-	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)
-
+	client, body, ok := h.readQuestion(w, r)
+	if !ok {
 		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), client.Unmap(), peer.Unmap(), true)
+	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()
 	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)
@@ -181,11 +199,70 @@ 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, 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 {
+// 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 {
 	sent := r.Clone(r.Context())
 	announced := sent.Header.Get(ContentLengthHeader)
 
@@ -202,55 +279,34 @@ func asTheVisitorSentIt(r *http.Request) *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, 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.
+// allow answers a question with DispositionAllow and, while
+// SWWAF_ADD_LOOKUP_HEADERS is set, the client's AS number and country.
 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)
 }
 
-// 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
+// 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)
 }
 
 // deny answers a question with what the visitor is to get for r.
@@ -271,7 +327,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. A report writes no log line.
+// rproxy and the admin's tools, not visitors.
 func (h *handler) answerOwnEndpoint(w http.ResponseWriter, r *http.Request) {
 	if r.Method == http.MethodPost && r.URL.Path == ReportPath {
 		h.takeReport(w, r)
@@ -294,57 +350,115 @@ 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, and ignores the report otherwise.
+// names, if it holds that request's decision, and ignores the report
+// otherwise.
 func (h *handler) takeReport(w http.ResponseWriter, r *http.Request) {
-	var report Report
-
-	err := json.NewDecoder(http.MaxBytesReader(w, r.Body, reportBodyMaxBytes)).
-		Decode(&report)
-	if err != nil || report.RequestBytes < 0 || report.ResponseBytes < 0 {
+	report, err := readReport(w, r)
+	if err != nil {
+		h.processLog.Warn("a report is refused", "error", err.Error())
 		http.Error(w, "the body is not a report", http.StatusBadRequest)
 
 		return
 	}
 
-	rq, held := h.awaitingReport.Peek(report.RequestID)
+	held, found := h.awaitingReport.Peek(report.RequestID)
 	// Remove reports true to one report only, of several that name the id.
-	if held && h.awaitingReport.Remove(report.RequestID) {
-		rq.finishWith(report)
+	if found && held != nil && h.awaitingReport.Remove(report.RequestID) {
+		h.finishWith(held, report)
 	}
 
 	w.WriteHeader(http.StatusNoContent)
 }
 
-// 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{}
+// 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{},
+	}
 	rq.body.bytes.Store(report.RequestBytes)
 
-	rq.countBytes()
-	rq.countAnomalies()
-	rq.addToHistory()
-
+	rq.line.ServeWAFLine = requestlog.ServeWAFLineReport
 	rq.line.Status = report.Status
 	rq.line.RequestBytes = report.RequestBytes
 	rq.line.ResponseBytes = report.ResponseBytes
-	rq.h.metrics.RequestReported(&rq.line,
-		time.Duration(report.DurationTotal*float64(time.Millisecond)),
-		time.Duration(report.DurationUpstreamTotal*float64(time.Millisecond)))
+	rq.line.DurationTotal = report.DurationTotal
 
-	// 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)
+	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)))
 	}
+
+	rq.writeLine()
 }

internal/requestlog/requestlog.go

@@ -1,6 +1,6 @@
 // Package requestlog writes the lines smallwebwaf prints on stdout: one
-// JSON object per request, marked "type":"request", and the process's own
-// messages as JSON lines marked "type":"process".
+// JSON object per request, or two from servewaf, marked "type":"request", and
+// the process's own messages as JSON lines marked "type":"process".
 package requestlog
 
 import (
@@ -60,6 +60,16 @@ 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"
 
@@ -70,6 +80,9 @@ 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,15 +2,95 @@ 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) {
@@ -23,6 +103,7 @@ 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()