Leave SWWAF_RATE_LIMIT_EXEMPT_PATHS out of the request rate limits (closes #77)

A request is neither counted nor refused by the request rate limits
when its path as sent, the path the app receives, not percent-decoded,
starts with one of the comma-separated prefixes in
SWWAF_RATE_LIMIT_EXEMPT_PATHS, so /%61ssets/x is not under /assets/. A
request whose decoded path contains .. or a backslash, or whose path as
sent holds an encoded slash, is never exempt, since an app may act on
it as a path outside every prefix, such as /assets/..%2Flogin as
/login. The static lists, bans and the country lists still apply, and
its log line has no counts. The setting is empty by default, and a
prefix that does not start with / stops the start. README.md documents
it.

Model: opus-5-5

README.md

@@ -13,23 +13,23 @@ JSON log line for every request.
 
 Status: the first two milestones are built
 (https://git.eeqj.de/sneak/smallwebwaf/issues/13 and
-https://git.eeqj.de/sneak/smallwebwaf/issues/14), and so are six parts of
-milestone 3: the static lists, the bans that broken rate limits lead to and the
-JSON state files with your edits taken in while it runs, which come next in the
-build order, `observe` mode, which comes a little later, and the metrics
+https://git.eeqj.de/sneak/smallwebwaf/issues/14), and so are eight parts of
+milestone 3: the static lists, the bans that broken rate limits lead to, the
+JSON state files with your edits taken in while it runs and the paths the rate
+limits do not count, which come next in the build order, `observe` mode and the
+rest of the request log's fields, which come a little later, and the metrics
 endpoint and the header size and the idle time as settings, which come last in
-it; and, from the stage after it, remote log sending. `smallwebwaf` passes each
-request to the app and the app's answer back, unchanged, within its timeouts and
-size limits, works out each client's address, bans a client that sends too many
-requests, refuses a client that comes from a country you refuse or from a
-network you refuse, lets the networks you choose through, keeps its bans, each
-client's counters and history, and GeoJS's answers in JSON files across
-restarts, takes in your edits of those files while it runs, writes a JSON log
-line for every request, sends its log lines to a syslog server too if you name
-one, serves Prometheus metrics to a scraper that holds the metrics token, and in
-`observe` mode passes on the requests it would refuse, logging what it would
-have done with them. It comes as the image the app's own image is built on. The
-rest of the design comes after that, in the order of the build order in
+it. `smallwebwaf` passes each request to the app and the app's answer back,
+unchanged, within its timeouts and size limits, works out each client's address,
+bans a client that sends too many requests, not counting those for the paths you
+choose, refuses a client that comes from a country you refuse or from a network
+you refuse, lets the networks you choose through, keeps its bans, each client's
+counters and history, and GeoJS's answers in JSON files across restarts, takes
+in your edits of those files while it runs, writes a JSON log line for every
+request, serves Prometheus metrics to a scraper that holds the metrics token,
+and in `observe` mode passes on the requests it would refuse, logging what it
+would have done with them. It comes as the image the app's own image is built
+on. The rest of the design comes after that, in the order of the build order in
 [`SPEC.md`](SPEC.md). The survey of existing tools that led to the design is in
 [`EVALUATION.md`](EVALUATION.md).
 
@@ -68,7 +68,9 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set.
   address outside `SWWAF_TRUSTED_PROXIES` is the client; if every address in it
   is inside, the leftmost is, and with no header the peer is. The app sees what
   it would see from traefik directly: the same `Host`, the same
-  `X-Forwarded-Proto`, and `X-Forwarded-For` with the peer added at the end.
+  `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
   response has started gets `smallwebwaf`'s own answer: `408` for a client too
   slow to send its request, `413` for a request body that is too large, `504`
@@ -82,12 +84,15 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set.
 - 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
-  bans the client. A client is one IPv4 address, or one IPv6 /64, since one
-  abuser usually holds a whole /64. Each window is counted in two fixed buckets,
-  the earlier one weighted by how much of it the window still covers. At most
-  20,000 clients are kept, the least recently seen dropped first, with their
-  history, and a restart gives no client a fresh allowance (see "State files"
-  below).
+  bans the client. A request whose path starts with one of
+  `SWWAF_RATE_LIMIT_EXEMPT_PATHS`, as that setting below describes, is neither
+  counted nor refused by the rate limits; the static lists, bans and the country
+  lists still apply to it. A client is one IPv4 address, or one IPv6 /64, since
+  one abuser usually holds a whole /64. Each window is counted in two fixed
+  buckets, the earlier one weighted by how much of it the window still covers.
+  At most 20,000 clients are kept, the least recently seen dropped first, with
+  their history, and a restart gives no client a fresh allowance (see "State
+  files" below).
 - Bans a client that breaks a rate limit, as "Bans" in [`SPEC.md`](SPEC.md)
   describes: the first ban lasts an hour, and a limit broken again within a day
   of a ban ending bans for three times as long as that ban, so 1, 3, 9, 27 and
@@ -146,9 +151,6 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set.
   passed to the app: a banned client stays refused, and each counts toward the
   client's rate limits. None of them reaches the app.
 - Writes a line in the request log for each request (see "Request log" below).
-- Sends every line it writes on stdout to a syslog server as well, while
-  `SWWAF_LOG_REMOTE_URL` names one (see "Sending the log to a syslog server"
-  below).
 
 ## Settings
 
@@ -159,6 +161,11 @@ it, and the effective settings are logged at start.
 - `SWWAF_LISTEN_ADDR` (default `:8080`): where `smallwebwaf` listens.
 - `SWWAF_UPSTREAM_URL` (default `http://127.0.0.1:8081`): the app, as `http` or
   `https`, a host and an optional port, and nothing more.
+- `SWWAF_INSTANCE_NAME` (default: the host's name, which docker sets to the
+  first 12 characters of the container's id unless the deployment names one):
+  the name each request log line gives as `instance`. Set it, for example to
+  `fsn1app1/gitea`, for a name that stays the same when a deploy replaces the
+  container, and that tells instances apart when several log to one place.
 - `SWWAF_MODE` (default `enforce`): `enforce`, or `observe` to pass on the
   requests `smallwebwaf` would refuse and log what it would have done (see "What
   it does so far" above).
@@ -197,6 +204,20 @@ it, and the effective settings are logged at start.
   requests a client may make in a minute, an hour and a day. The defaults are
   several times what one busy person produces, since a browser loading a heavy
   page makes a few hundred requests and several people often share one address.
+- `SWWAF_RATE_LIMIT_EXEMPT_PATHS` (default empty): path prefixes whose requests
+  the rate limits neither count nor refuse, such as `/assets/` for static
+  assets; each starts with `/`. A request whose path, percent-decoded, contains
+  `..` anywhere or a backslash, or whose path as sent holds an encoded slash
+  (`%2F` or `%2f`), is never exempt, since the app may act on it as a path
+  outside every prefix: `/assets/..%2Flogin` as `/login`. Any other request is
+  exempt when its path as sent, the path the app receives, before any query
+  string and not percent-decoded, starts with a prefix, character for character.
+  `/assets/` matches `/assets/app.js` and `/assets/`, but not `/assets`,
+  `/Assets/app.js`, `/%61ssets/app.js`, `/static/assets/app.js`,
+  `/static/../assets/app.js` or `/assets%2Fapp.js`. A character the client sends
+  percent-encoded, such as a space, is written percent-encoded in a prefix, as
+  in `/my%20files/`, and there are no wildcards: `*` is a character like any
+  other.
 - `SWWAF_DENIED_COUNTRIES` (default empty): countries whose clients are refused,
   for example `cn,ru,kp`.
 - `SWWAF_EXCLUSIVELY_ALLOWED_COUNTRIES` (default empty): when set, the only
@@ -226,29 +247,19 @@ it, and the effective settings are logged at start.
   `bans.json` is written, with every ban made in between.
 - `SWWAF_STATE_COUNTER_INTERVAL` (default `15m`): how often every state file is
   written.
+- `SWWAF_LOG_REQUEST_HEADERS` (default
+  `accept,accept-language,accept-encoding,content-type,origin,range`): the
+  request headers whose values the request log gives, in either case.
+  `Authorization`, `Cookie` and `Set-Cookie` are never logged, even when listed
+  (see "Request log" below). An entry naming `Host` or `Transfer-Encoding` stops
+  the start, since Go's HTTP server takes both out of the request; the request's
+  host is the field `host`.
 - `SWWAF_METRICS_TOKEN` (default unset): the token a scraper sends for the
   metrics, a long random value. While it is unset the metrics are off; one
   shorter than 32 characters stops the start. The settings logged at start show
   `********` in its place.
 - `SWWAF_METRICS_TOP_N` (default `50`): how many countries get series of their
   own in the metrics by country; the others are counted as `other`.
-- `SWWAF_LOG_REMOTE_URL` (default unset): a syslog server that every line on
-  stdout is also sent to, as `syslog+udp://`, `syslog+tcp://` or `syslog+tls://`
-  with a host and a port, such as `syslog+tls://logs.example:6514`. Unset or
-  empty, nothing is sent.
-- `SWWAF_LOG_REMOTE_TLS_CA_FILE` (default unset): a file of PEM certificates,
-  which the certificate of a `syslog+tls` server must chain to instead of the
-  host's own. A file that cannot be read or holds no certificate stops the
-  start.
-- `SWWAF_LOG_REMOTE_BUFFER` (default `10000`): the most lines held while they
-  wait to be sent.
-- `SWWAF_LOG_REMOTE_FACILITY` (default `local0`): the syslog facility the lines
-  are sent with: `kern`, `user`, `mail`, `daemon`, `auth`, `syslog`, `lpr`,
-  `news`, `uucp`, `cron`, `authpriv`, `ftp`, or `local0` to `local7`.
-- `SWWAF_LOG_REMOTE_APP_NAME` (default the host's name): the app name the lines
-  are sent with, 1 to 48 printable ASCII characters without a space. While
-  `SWWAF_LOG_REMOTE_URL` is set, a default that is not such a name stops the
-  start too.
 
 Durations are in Go's syntax, with `d` for days (`90s`, `15m`, `7d`). Sizes are
 bytes, with an optional `K`, `M` or `G`, which are powers of 1024 (`1K` is 1024
@@ -258,8 +269,8 @@ ISO 3166-1 assigns today, and `xk` for Kosovo, in either case (`de` and `DE` are
 the same); any other code, such as `nk` (North Korea is `kp`) or the withdrawn
 `su`, stops the start, and so does a code on both country lists. `off` switches
 a timeout, a size limit or a rate limit off;
-`SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES`, the ban settings, the state settings,
-`SWWAF_METRICS_TOP_N` and `SWWAF_LOG_REMOTE_BUFFER` cannot be off.
+`SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES`, the ban settings, the state settings
+and `SWWAF_METRICS_TOP_N` cannot be off.
 
 Several limits are fixed rather than settings. At most 20,000 clients are kept,
 with their counters and history, and an IPv6 client is counted by its /64. A new
@@ -272,18 +283,42 @@ GeoJS are kept, for 7 days each.
 refused ones included:
 
 ```
-{"type":"request","time":"2026-10-03T12:00:00.123Z","client_ip":"203.0.113.9","peer_ip":"172.18.0.2","country":"DE","method":"GET","host":"app.example","path":"/","query":"","protocol":"HTTP/1.1","status":200,"upstream_status":200,"request_bytes":0,"response_bytes":5120,"referer":"","user_agent":"curl/8.9.1","action":"forward","duration_total":3.217,"duration_upstream_total":3.104}
+{"type":"request","time":"2026-10-03T12:00:00.123Z","instance":"fsn1app1/gitea","client_ip":"203.0.113.9","method":"GET","scheme":"https","host":"app.example","path":"/","query":"","protocol":"HTTP/1.1","status":200,"request_bytes":0,"response_bytes":5120,"referer":"","user_agent":"curl/8.9.1","request_id":"7Q2NHZ4KJ3VXW5YB6R3MEFTD2A","peer_ip":"172.18.0.2","forwarded_for":"203.0.113.9","client_group":"203.0.113.9/32","country":"DE","request_headers":{"accept":"*/*"},"response_content_type":"text/html; charset=utf-8","upstream_status":200,"action":"forward","counts":{"minute":1,"hour":12,"day":40},"duration_total":3.217,"duration_checks":0.041,"duration_upstream_connect":0.052,"duration_upstream_first_byte":2.874,"duration_upstream_total":3.104}
 ```
 
-- `time` is when the request arrived, in UTC. `peer_ip` is the TCP peer,
-  normally traefik. `path` and `query` are as the client sent them.
+A field that does not apply to a request is left out of its line, apart from
+`type`, the fields from `time` to `user_agent`, `request_id`, `peer_ip`,
+`client_group`, `country`, `action` and `duration_total`, which every line has.
+
+- `time` is when the request arrived, in UTC. `instance` is
+  `SWWAF_INSTANCE_NAME`. `scheme` is the `X-Forwarded-Proto` a trusted proxy
+  sent, and otherwise `http`. `path` and `query` are as the client sent them.
+- `request_id` is the `X-Request-ID` a trusted proxy sent, or a new random one
+  of 26 letters and digits when it sent none, or when the peer is not a trusted
+  proxy. A request passed to the app takes it there in `X-Request-ID`.
+- `peer_ip` is the TCP peer, normally traefik. `forwarded_for` is the
+  `X-Forwarded-For` header as received, several lines of it joined with `, `.
+  `client_group` is the client as the rate limits count it: its IPv4 address as
+  a /32, or the /64 of its IPv6 address.
 - `country` is the client's country as GeoJS places it. It is empty with neither
   country list set, for a client in `SWWAF_ALLOW_NETS` or `SWWAF_DENY_NETS`, for
   a client on a private, loopback or link-local address, when GeoJS cannot place
   the client or has not answered in time, and for a request whose client a ban
   covers, even when the client's country is known.
+- `content_type` is the request's `Content-Type`, and `content_length` the
+  length the request announced for its body, which is left out for none or zero.
+- `request_headers` are the request's headers that `SWWAF_LOG_REQUEST_HEADERS`
+  names, by name in lower case, several lines of one joined with `, `.
+  `Authorization`, `Cookie` and `Set-Cookie` are never among them, whatever the
+  setting says: `has_authorization` and `has_cookie` are there instead, and
+  true, when the request has an `Authorization` or a `Cookie` header.
+- `websocket` is there, and true, when the app switched the connection to
+  another protocol, as it does for a WebSocket.
 - `status` is what the client was sent, `0` if nothing was; `upstream_status` is
   what the app answered, and is left out when the app did not answer.
+- `response_content_type`, `cache_control` and `location` are the
+  `Content-Type`, `Cache-Control` and `Location` headers of the answer: the
+  app's, as passed on, or those of `smallwebwaf`'s own answer.
 - `request_bytes` and `response_bytes` count body bytes.
 - `action` is `forward` for a request passed to the app, `denied` for one
   refused because its client is in `SWWAF_DENY_NETS`, `banned` for one refused
@@ -299,6 +334,16 @@ refused ones included:
   `banned`, `country_denied` or `rate_limited`. `action` then names what was
   done: `forward` for a request passed to the app, and another action, such as
   `too_large`, for one a size or time limit refused.
+- `counts` gives the client's requests in the minute, the hour and the day as
+  the rate limits count them, this request included: in each window, those in
+  the bucket under way and a share of those in the bucket before, so a count can
+  have a fraction. For a request that broke a limit, they are the counts that
+  broke it. It is left out for a request the rate limits do not count: the
+  health check, one from a client in `SWWAF_ALLOW_NETS` or
+  `SWWAF_RATE_LIMIT_EXEMPT_NETS`, one for a path that
+  `SWWAF_RATE_LIMIT_EXEMPT_PATHS` exempts, and one that `SWWAF_DENY_NETS`, a ban
+  or the country lists refuse, or would refuse in `observe` mode. The byte
+  totals come with the byte limits.
 - `limit_hit` is there for a request that broke a rate limit, and names the
   window whose limit it went over: `minute`, `hour` or `day`, the shortest if it
   went over several. `offence` is then `limit`.
@@ -306,10 +351,19 @@ refused ones included:
   or in `observe` mode would have been refused under one, and gives when the ban
   ends, in the same form as `time`, or `permanent`.
 - `aborted` is there, and true, when the client went away early.
-- `duration_total` and `duration_upstream_total` are in milliseconds.
+- The timings are in milliseconds, to the microsecond. `duration_total` runs
+  from when the request's headers had been read to when its line is written, and
+  `duration_checks` over the same start to when the checks were done; the health
+  check runs none, and its line has no `duration_checks`.
+  `duration_upstream_connect`, `duration_upstream_first_byte` and
+  `duration_upstream_total` are there for a request passed to the app, and run
+  from when it was handed to the app: until there was a connection to it, new or
+  kept open from an earlier request, until the first byte of its answer arrived,
+  and until the end. The first two are left out when that never happened, as for
+  an app that cannot be reached.
 
-No body and no other header is logged. `smallwebwaf`'s own messages (start, the
-settings, stop, errors) share the stream as JSON lines marked
+No body is logged, and no header but those above. `smallwebwaf`'s own messages
+(start, the settings, stop, errors) share the stream as JSON lines marked
 `"type":"process"`.
 
 Go's HTTP server, on which `smallwebwaf` is built, reads a request's line and
@@ -319,30 +373,6 @@ which it answers `431`, headers slower than `SWWAF_CLIENT_REQUEST_TIMEOUT`,
 whose connection it closes without an answer, and requests it cannot read at
 all, which it answers itself, mostly with `400`.
 
-### Sending the log to a syslog server
-
-While `SWWAF_LOG_REMOTE_URL` is set, every line `smallwebwaf` writes on stdout,
-request lines and its own, is also sent to that syslog server, as the message of
-an RFC 5424 record: one record to a datagram over UDP, and over TCP and TLS each
-record after its length in bytes and a space. A record gives the facility
-`SWWAF_LOG_REMOTE_FACILITY` names, the severity informational, the time the line
-was written, in the same form as a request line's `time`, the host's name, and
-the app name `SWWAF_LOG_REMOTE_APP_NAME` gives. stdout is unchanged.
-
-The lines wait in a buffer of `SWWAF_LOG_REMOTE_BUFFER` lines and are sent from
-there, so a server that is slow or cannot be reached never holds up a request or
-stdout. When the buffer is full, its oldest line is dropped to make room. A line
-whose sending fails is dropped too, and the connection is made again at once. A
-failed attempt to connect is logged and followed by the next a second later,
-twice as long after each further failure up to a minute, and a second again once
-a connection is made. UDP gives no sign of what arrives, and over TCP and TLS a
-line sent on a connection the server has just closed can be lost before a
-failure shows; such a loss is not counted.
-
-As `smallwebwaf` stops, it sends the lines still waiting, on the connection open
-or a new one, for at most two seconds, and gives up the rest; stdout has carried
-them.
-
 ## State files
 
 `smallwebwaf` keeps its state in memory and a copy of it in three JSON files in
@@ -460,11 +490,6 @@ other request. No metric carries a client's address.
   `smallwebwaf_state_file_edits_taken_in_total`: your edits taken in, and
   `smallwebwaf_state_file_edits_set_aside_total`: those renamed to `<name>.bad`
   because they would stop the start.
-- While `SWWAF_LOG_REMOTE_URL` is set,
-  `smallwebwaf_remote_log_lines_sent_total`: the lines sent to it;
-  `smallwebwaf_remote_log_lines_dropped_total`: those dropped, from a full
-  buffer or because their sending failed; and
-  `smallwebwaf_remote_log_buffer_depth`: those waiting in the buffer.
 - Go's own `go_` metrics and the process's `process_` metrics.
 
 The requests Go's HTTP server ends before `smallwebwaf` sees them (see "Request
@@ -770,10 +795,6 @@ addresses are never sent to GeoJS.
   one while running, and writes them when they are due and at the stop.
 - `internal/requestlog`: the lines on stdout: the request log line and the
   process's own messages.
-- `internal/remotelog`: sends the lines on stdout to `SWWAF_LOG_REMOTE_URL`,
-  each as a syslog record, from a buffer of its own. It is written with the
-  standard library alone, whose `log/syslog` writes only the older syslog
-  format.
 - `Dockerfile`: the lint and test phases, then the image, whose last stage
   installs Ubuntu's packages, nixpkgs, `runsvinit` and `smallwebwaf`, with
   `share/smallwebwaf.run` as runit's `run` script for `smallwebwaf`.
@@ -828,8 +849,7 @@ so that they run in minimal containers.
 
 ## TODO
 
-- The rest of milestone 3: exemptions and the rest of the request log's fields;
-  then the rest of the design, in the order of the build order in
+- The rest of the design, in the order of the build order in
   [`SPEC.md`](SPEC.md).
 
 ## Documents

internal/config/config.go

@@ -4,7 +4,6 @@
 package config
 
 import (
-	"crypto/x509"
 	"errors"
 	"fmt"
 	"log/slog"
@@ -20,8 +19,6 @@ import (
 	"strings"
 	"time"
 	"unicode/utf8"
-
-	"sneak.berlin/go/smallwebwaf/internal/remotelog"
 )
 
 // Config is smallwebwaf's settings. A timeout, size or rate limit of zero
@@ -31,6 +28,10 @@ type Config struct {
 	ListenAddr string
 	// UpstreamURL is the app (SWWAF_UPSTREAM_URL).
 	UpstreamURL *url.URL
+	// InstanceName is the name each request log line gives as instance
+	// (SWWAF_INSTANCE_NAME), by default the host's name, which docker sets
+	// to the first 12 characters of the container's id.
+	InstanceName string
 	// Observe is true in observe mode, when SWWAF_MODE is observe rather
 	// than enforce: a request that SWWAF_DENY_NETS, a ban, the country
 	// lists or a rate limit would refuse is passed to the app instead, and
@@ -79,6 +80,10 @@ type Config struct {
 	RateLimitPerMinute int64
 	RateLimitPerHour   int64
 	RateLimitPerDay    int64
+	// RateLimitExemptPaths are the path prefixes whose requests the rate
+	// limits neither count nor refuse (SWWAF_RATE_LIMIT_EXEMPT_PATHS).
+	// Each starts with /.
+	RateLimitExemptPaths []string
 	// DeniedCountries are the countries whose clients are refused
 	// (SWWAF_DENIED_COUNTRIES). ExclusivelyAllowedCountries, when not
 	// empty, are the only countries whose clients are let through
@@ -113,26 +118,15 @@ type Config struct {
 	StateDir             string
 	StateWriteDelay      time.Duration
 	StateCounterInterval time.Duration
+	// LogRequestHeaders are the request headers whose values the request
+	// log gives, in lower case (SWWAF_LOG_REQUEST_HEADERS).
+	LogRequestHeaders []string
 	// MetricsToken is the bearer token a scraper sends for the metrics
 	// (SWWAF_METRICS_TOKEN), "" while it is unset and the metrics are off.
 	// MetricsTopN is how many countries get series of their own in the
 	// metrics (SWWAF_METRICS_TOP_N).
 	MetricsToken string
 	MetricsTopN  int
-	// LogRemoteURL is where every line on stdout is also sent
-	// (SWWAF_LOG_REMOTE_URL), nil while it is unset and nothing is sent.
-	// LogRemoteTLSCAs are the certificates a syslog+tls endpoint's
-	// certificate must chain to (SWWAF_LOG_REMOTE_TLS_CA_FILE), nil while
-	// it is unset and the host's own are used. LogRemoteBuffer is the most
-	// lines held while they wait to be sent (SWWAF_LOG_REMOTE_BUFFER).
-	// LogRemoteFacility is the number of the syslog facility
-	// (SWWAF_LOG_REMOTE_FACILITY), and LogRemoteAppName the APP-NAME
-	// (SWWAF_LOG_REMOTE_APP_NAME), of the records the lines are sent in.
-	LogRemoteURL      *url.URL
-	LogRemoteTLSCAs   *x509.CertPool
-	LogRemoteBuffer   int
-	LogRemoteFacility int
-	LogRemoteAppName  string
 
 	// settings are the values read, as given or by default, for the
 	// log line at start.
@@ -173,6 +167,11 @@ var (
 			"such as http://127.0.0.1:8081")
 	errNotCountry = errors.New(
 		"is not a two-letter country code such as de or kp")
+	errNotHeaderName = errors.New(
+		"is not a header name such as accept-language")
+	errHeaderTakenOut = errors.New(
+		"is taken out of every request by Go's HTTP server, so it can never " +
+			"be logged")
 	errOnBothLists          = errors.New("is in SWWAF_DENIED_COUNTRIES too")
 	errNotOver4K            = errors.New("is not a size of more than 4K, such as 32K")
 	errNotDurationAboveZero = errors.New(
@@ -186,13 +185,8 @@ var (
 		"is not an absolute path, such as /var/lib/smallwebwaf")
 	errShortToken    = errors.New("is shorter than 32 characters")
 	errNotMode       = errors.New("is not enforce or observe")
-	errNotLogRemoteURL = errors.New(
-		"is not syslog+udp, syslog+tcp or syslog+tls with a host and a port, " +
-			"and nothing more, such as syslog+tls://logs.example:6514")
-	errNoCertificate = errors.New("holds no PEM certificate")
-	errNotFacility   = errors.New("is not a syslog facility such as local0 or daemon")
-	errNotAppName    = errors.New(
-		"is not 1 to 48 printable ASCII characters without a space, such as gitea")
+	errNotPathPrefix = errors.New(
+		"is not a path prefix starting with /, such as /assets/")
 )
 
 // FromEnvironment reads the settings with lookupEnv, normally
@@ -200,9 +194,11 @@ var (
 // that is set but invalid is an error that names it.
 func FromEnvironment(lookupEnv func(string) (string, bool)) (*Config, error) {
 	env := &environment{lookupEnv: lookupEnv}
+	hostname, _ := os.Hostname() // "" when the host has no name to give
 	cfg := &Config{
 		ListenAddr:           env.address("SWWAF_LISTEN_ADDR", ":8080"),
 		UpstreamURL:          env.appURL("SWWAF_UPSTREAM_URL", "http://127.0.0.1:8081"),
+		InstanceName:         env.value("SWWAF_INSTANCE_NAME", hostname),
 		Observe:              env.observe("SWWAF_MODE", "enforce"),
 		TrustedProxies:       env.netblocks("SWWAF_TRUSTED_PROXIES", privateRanges),
 		ClientRequestTimeout: env.duration("SWWAF_CLIENT_REQUEST_TIMEOUT", "60s"),
@@ -220,6 +216,7 @@ func FromEnvironment(lookupEnv func(string) (string, bool)) (*Config, error) {
 		RateLimitPerMinute:      env.count("SWWAF_RATE_LIMIT_PER_MINUTE", "1000"),
 		RateLimitPerHour:        env.count("SWWAF_RATE_LIMIT_PER_HOUR", "10000"),
 		RateLimitPerDay:         env.count("SWWAF_RATE_LIMIT_PER_DAY", "50000"),
+		RateLimitExemptPaths:    env.pathPrefixes("SWWAF_RATE_LIMIT_EXEMPT_PATHS", ""),
 		DeniedCountries:         env.countries("SWWAF_DENIED_COUNTRIES", ""),
 		ExclusivelyAllowedCountries: env.countries(
 			"SWWAF_EXCLUSIVELY_ALLOWED_COUNTRIES", ""),
@@ -232,18 +229,12 @@ func FromEnvironment(lookupEnv func(string) (string, bool)) (*Config, error) {
 		StateDir:             env.absolutePath("SWWAF_STATE_DIR", "/var/lib/smallwebwaf"),
 		StateWriteDelay:      env.durationNotOff("SWWAF_STATE_WRITE_DELAY", "10s"),
 		StateCounterInterval: env.durationNotOff("SWWAF_STATE_COUNTER_INTERVAL", "15m"),
+		LogRequestHeaders: env.headerNames("SWWAF_LOG_REQUEST_HEADERS",
+			"accept,accept-language,accept-encoding,content-type,origin,range"),
 		MetricsToken: env.token("SWWAF_METRICS_TOKEN"),
 		MetricsTopN:  env.numberNotOff("SWWAF_METRICS_TOP_N", "50"),
-		LogRemoteURL:         env.logRemoteURL("SWWAF_LOG_REMOTE_URL"),
-		LogRemoteTLSCAs:      env.certificates("SWWAF_LOG_REMOTE_TLS_CA_FILE"),
-		LogRemoteBuffer:      env.numberNotOff("SWWAF_LOG_REMOTE_BUFFER", "10000"),
-		LogRemoteFacility:    env.facility("SWWAF_LOG_REMOTE_FACILITY", "local0"),
 	}
 
-	hostname, _ := os.Hostname() // "" when the host has no name to give
-	cfg.LogRemoteAppName = env.appName("SWWAF_LOG_REMOTE_APP_NAME", hostname,
-		cfg.LogRemoteURL != nil)
-
 	for _, country := range cfg.ExclusivelyAllowedCountries {
 		if slices.Contains(cfg.DeniedCountries, country) {
 			env.check("SWWAF_EXCLUSIVELY_ALLOWED_COUNTRIES",
@@ -366,6 +357,14 @@ func (e *environment) count(name, defaultValue string) int64 {
 	return count
 }
 
+// pathPrefixes reads a setting that is a list of path prefixes.
+func (e *environment) pathPrefixes(name, defaultValue string) []string {
+	prefixes, err := parsePathPrefixes(e.value(name, defaultValue))
+	e.check(name, err)
+
+	return prefixes
+}
+
 // countries reads a setting that is a list of countries.
 func (e *environment) countries(name, defaultValue string) []string {
 	countries, err := parseCountries(e.value(name, defaultValue))
@@ -374,6 +373,15 @@ func (e *environment) countries(name, defaultValue string) []string {
 	return countries
 }
 
+// headerNames reads a setting that is a list of header names, and
+// returns them in lower case.
+func (e *environment) headerNames(name, defaultValue string) []string {
+	headers, err := parseHeaderNames(e.value(name, defaultValue))
+	e.check(name, err)
+
+	return headers
+}
+
 // durationNotOff reads a setting that is a duration and, unlike a
 // timeout, cannot be off.
 func (e *environment) durationNotOff(name, defaultValue string) time.Duration {
@@ -438,68 +446,6 @@ func (e *environment) token(name string) string {
 	return value
 }
 
-// logRemoteURL reads the setting that is where every log line is also
-// sent. Unset or empty, it is nil, and nothing is sent.
-func (e *environment) logRemoteURL(name string) *url.URL {
-	value := e.value(name, "")
-	if value == "" {
-		return nil
-	}
-
-	remote, err := parseLogRemoteURL(value)
-	e.check(name, err)
-
-	return remote
-}
-
-// certificates reads a setting that is the path of a file of PEM
-// certificates. Unset or empty, it is nil.
-func (e *environment) certificates(name string) *x509.CertPool {
-	path := e.value(name, "")
-	if path == "" {
-		return nil
-	}
-
-	pem, err := os.ReadFile(path) //nolint:gosec // a file the admin names
-	if err != nil {
-		e.check(name, fmt.Errorf("cannot be read: %w", err))
-
-		return nil
-	}
-
-	pool := x509.NewCertPool()
-	if !pool.AppendCertsFromPEM(pem) {
-		e.check(name, fmt.Errorf("%q %w", path, errNoCertificate))
-
-		return nil
-	}
-
-	return pool
-}
-
-// facility reads a setting that is a syslog facility, and returns its
-// number.
-func (e *environment) facility(name, defaultValue string) int {
-	number, err := parseFacility(e.value(name, defaultValue))
-	e.check(name, err)
-
-	return number
-}
-
-// appName reads the setting that is the APP-NAME of the records the log
-// lines are sent in. Its value is checked when it is set, and while lines
-// are sent, when they would be sent with its default.
-func (e *environment) appName(name, defaultValue string, sending bool) string {
-	_, set := e.lookupEnv(name)
-
-	value := e.value(name, defaultValue)
-	if (set || sending) && !isAppName(value) {
-		e.check(name, fmt.Errorf("%q %w", value, errNotAppName))
-	}
-
-	return value
-}
-
 // parseDuration reads a duration in Go's syntax, such as 90s or 15m, a
 // whole number of days such as 7d, or off.
 func parseDuration(value string) (time.Duration, error) {
@@ -706,6 +652,23 @@ func parseNetblock(value string) (netip.Prefix, error) {
 	return netip.PrefixFrom(addr, addr.BitLen()), nil
 }
 
+// parsePathPrefixes reads a comma-separated list of path prefixes, each
+// starting with /.
+func parsePathPrefixes(value string) ([]string, error) {
+	prefixes, err := parseList(value)
+	if err != nil {
+		return nil, err
+	}
+
+	for _, prefix := range prefixes {
+		if !strings.HasPrefix(prefix, "/") {
+			return nil, fmt.Errorf("%q %w", prefix, errNotPathPrefix)
+		}
+	}
+
+	return prefixes, nil
+}
+
 // countryCodes are the two-letter codes ISO 3166-1 assigns today, and XK,
 // the code in common use for Kosovo. golang.org/x/text/language cannot
 // check them: it also takes withdrawn codes such as su, and reserved ones
@@ -762,6 +725,44 @@ func parseCountries(value string) ([]string, error) {
 	return countries, nil
 }
 
+// headerNameChars are the characters RFC 9110 allows in a header name:
+// letters, digits and these marks.
+const headerNameChars = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz" +
+	"0123456789!#$%&'*+-.^_`|~"
+
+// parseHeaderNames reads a comma-separated list of header names in either
+// case, and returns them in lower case. Host and Transfer-Encoding are
+// refused: Go's HTTP server takes them out of the request's headers.
+func parseHeaderNames(value string) ([]string, error) {
+	items, err := parseList(value)
+	if err != nil {
+		return nil, err
+	}
+
+	headers := make([]string, 0, len(items))
+
+	for _, item := range items {
+		for _, char := range item {
+			if !strings.ContainsRune(headerNameChars, char) {
+				return nil, fmt.Errorf("%q %w", item, errNotHeaderName)
+			}
+		}
+
+		header := strings.ToLower(item)
+		switch header {
+		case "host":
+			return nil, fmt.Errorf("%q %w; the request's host is the field host",
+				item, errHeaderTakenOut)
+		case "transfer-encoding":
+			return nil, fmt.Errorf("%q %w", item, errHeaderTakenOut)
+		}
+
+		headers = append(headers, header)
+	}
+
+	return headers, nil
+}
+
 // parseListenAddr checks an address to listen on: an optional host and a
 // port number.
 func parseListenAddr(value string) (string, error) {
@@ -804,64 +805,3 @@ func parseUpstreamURL(value string) (*url.URL, error) {
 
 	return upstream, nil
 }
-
-// parseLogRemoteURL reads where every log line is also sent:
-// syslog+udp, syslog+tcp or syslog+tls, a host and a port from 1 to
-// 65535, and nothing else.
-func parseLogRemoteURL(value string) (*url.URL, error) {
-	remote, err := url.Parse(value)
-	if err != nil {
-		return nil, fmt.Errorf("%q %w", value, errNotLogRemoteURL)
-	}
-
-	schemes := []string{remotelog.SchemeUDP, remotelog.SchemeTCP, remotelog.SchemeTLS}
-	port, err := strconv.ParseUint(remote.Port(), 10, 16)
-
-	onlySchemeHostAndPort := slices.Contains(schemes, remote.Scheme) &&
-		remote.Hostname() != "" && err == nil && port != 0 &&
-		remote.User == nil && remote.Opaque == "" &&
-		(remote.Path == "" || remote.Path == "/") &&
-		remote.RawQuery == "" && remote.Fragment == ""
-	if !onlySchemeHostAndPort {
-		return nil, fmt.Errorf("%q %w", value, errNotLogRemoteURL)
-	}
-
-	return remote, nil
-}
-
-// parseFacility reads the name of a syslog facility, and returns its
-// number, as RFC 5424 numbers them.
-func parseFacility(value string) (int, error) {
-	//nolint:mnd // the facilities' numbers in RFC 5424
-	number, known := map[string]int{
-		"kern": 0, "user": 1, "mail": 2, "daemon": 3, "auth": 4, "syslog": 5,
-		"lpr": 6, "news": 7, "uucp": 8, "cron": 9, "authpriv": 10, "ftp": 11,
-		"local0": 16, "local1": 17, "local2": 18, "local3": 19,
-		"local4": 20, "local5": 21, "local6": 22, "local7": 23,
-	}[value]
-	if !known {
-		return 0, fmt.Errorf("%q %w", value, errNotFacility)
-	}
-
-	return number, nil
-}
-
-// appNameMaxLength is the most characters RFC 5424 allows in an
-// APP-NAME.
-const appNameMaxLength = 48
-
-// isAppName reports whether value can be an APP-NAME: 1 to
-// appNameMaxLength printable ASCII characters, none of them a space.
-func isAppName(value string) bool {
-	if value == "" || len(value) > appNameMaxLength {
-		return false
-	}
-
-	for _, char := range []byte(value) {
-		if char < '!' || char > '~' {
-			return false
-		}
-	}
-
-	return true
-}

internal/config/config_test.go

@@ -2,13 +2,11 @@ package config_test
 
 import (
 	"bytes"
-	"crypto/x509"
 	"encoding/json"
 	"log/slog"
 	"maps"
 	"net/netip"
 	"os"
-	"path/filepath"
 	"slices"
 	"strings"
 	"testing"
@@ -37,6 +35,7 @@ const (
 	rateLimitPerMinute      = "SWWAF_RATE_LIMIT_PER_MINUTE"
 	rateLimitPerHour        = "SWWAF_RATE_LIMIT_PER_HOUR"
 	rateLimitPerDay         = "SWWAF_RATE_LIMIT_PER_DAY"
+	rateLimitExemptPaths    = "SWWAF_RATE_LIMIT_EXEMPT_PATHS"
 	deniedCountries         = "SWWAF_DENIED_COUNTRIES"
 	allowedCountries        = "SWWAF_EXCLUSIVELY_ALLOWED_COUNTRIES"
 	banResponse             = "SWWAF_BAN_RESPONSE"
@@ -50,26 +49,13 @@ const (
 	stateCounterInterval    = "SWWAF_STATE_COUNTER_INTERVAL"
 	metricsToken            = "SWWAF_METRICS_TOKEN" //nolint:gosec // the setting's name
 	metricsTopN             = "SWWAF_METRICS_TOP_N"
-	logRemoteURL            = "SWWAF_LOG_REMOTE_URL"
-	logRemoteTLSCAFile      = "SWWAF_LOG_REMOTE_TLS_CA_FILE"
-	logRemoteBuffer         = "SWWAF_LOG_REMOTE_BUFFER"
-	logRemoteFacility       = "SWWAF_LOG_REMOTE_FACILITY"
-	logRemoteAppName        = "SWWAF_LOG_REMOTE_APP_NAME"
+	instanceName            = "SWWAF_INSTANCE_NAME"
+	logRequestHeaders       = "SWWAF_LOG_REQUEST_HEADERS"
 )
 
-// testCA is a CA certificate, of which only that it reads matters here.
-const testCA = `-----BEGIN CERTIFICATE-----
-MIIBkzCCATmgAwIBAgIUeySaE27dnr6A2HijrMB13gTLUKIwCgYIKoZIzj0EAwIw
-HjEcMBoGA1UEAwwTc21hbGx3ZWJ3YWYgdGVzdCBDQTAgFw0yNjEwMDYxNDI2MTNa
-GA8yMTI2MDkxMjE0MjYxM1owHjEcMBoGA1UEAwwTc21hbGx3ZWJ3YWYgdGVzdCBD
-QTBZMBMGByqGSM49AgEGCCqGSM49AwEHA0IABKDEhcWKKhet2KgSdME+iEPxyEyn
-2sd9IdElbt8DM2SfCdB2JsXo0C07UNZaywMPMfn/n8LNI/PKwu+N2uX7gfSjUzBR
-MB0GA1UdDgQWBBRZo3BPLv0KbV4drw6JI1JIUKmoRzAfBgNVHSMEGDAWgBRZo3BP
-Lv0KbV4drw6JI1JIUKmoRzAPBgNVHRMBAf8EBTADAQH/MAoGCCqGSM49BAMCA0gA
-MEUCICC5k+76UpWoSwVbZA+atu5WcALEOJGqwOUWua3zemhcAiEA8Hfdxgwp0z2v
-rlG9y/jrJb6ORy3kTLWo2EA0BA67vuI=
------END CERTIFICATE-----
-`
+// defaultLogRequestHeaders is the default of SWWAF_LOG_REQUEST_HEADERS.
+const defaultLogRequestHeaders = "accept,accept-language,accept-encoding," +
+	"content-type,origin,range"
 
 // token is a token of 32 characters, the shortest allowed.
 const token = "0123456789abcdef0123456789abcdef"
@@ -142,6 +128,22 @@ func TestDefaults(t *testing.T) {
 	wantNetblocks(t, cfg.DenyNets)
 	wantCountries(t, deniedCountries, cfg.DeniedCountries)
 	wantCountries(t, allowedCountries, cfg.ExclusivelyAllowedCountries)
+
+	hostname, err := os.Hostname()
+	if err != nil || hostname == "" || cfg.InstanceName != hostname {
+		t.Errorf("%s is %q, want the host's name %q (%v)", instanceName,
+			cfg.InstanceName, hostname, err)
+	}
+
+	wantHeaders := strings.Split(defaultLogRequestHeaders, ",")
+	if !slices.Equal(cfg.LogRequestHeaders, wantHeaders) {
+		t.Errorf("%s gave %v, want %v", logRequestHeaders, cfg.LogRequestHeaders,
+			wantHeaders)
+	}
+
+	if len(cfg.RateLimitExemptPaths) != 0 {
+		t.Errorf("%s gave %v, want none", rateLimitExemptPaths, cfg.RateLimitExemptPaths)
+	}
 }
 
 func TestValuesAsSet(t *testing.T) {
@@ -166,6 +168,7 @@ func TestValuesAsSet(t *testing.T) {
 		rateLimitPerMinute:      "60",
 		rateLimitPerHour:        "600",
 		rateLimitPerDay:         "6000",
+		rateLimitExemptPaths:    "/assets/, /favicon.ico",
 		deniedCountries:         "cn, RU,kp,Xk",
 		allowedCountries:        "de",
 		banResponse:             "429",
@@ -218,133 +221,41 @@ func TestValuesAsSet(t *testing.T) {
 	wantNetblocks(t, cfg.DenyNets, "198.51.100.0/24")
 	wantCountries(t, deniedCountries, cfg.DeniedCountries, "CN", "RU", "KP", "XK")
 	wantCountries(t, allowedCountries, cfg.ExclusivelyAllowedCountries, "DE")
-}
 
-func TestRemoteLogSettingsDefaults(t *testing.T) {
-	t.Parallel()
-
-	cfg := fromEnvironment(t, environment{})
-	hostname, _ := os.Hostname()
-
-	if cfg.LogRemoteURL != nil || cfg.LogRemoteTLSCAs != nil ||
-		cfg.LogRemoteBuffer != 10000 || cfg.LogRemoteFacility != 16 ||
-		cfg.LogRemoteAppName != hostname {
-		t.Errorf("remote log settings %v, %v, %d, %d and %q, want no URL, no "+
-			"certificates, 10000, 16 and %q", cfg.LogRemoteURL, cfg.LogRemoteTLSCAs,
-			cfg.LogRemoteBuffer, cfg.LogRemoteFacility, cfg.LogRemoteAppName, hostname)
+	if !slices.Equal(cfg.RateLimitExemptPaths, []string{"/assets/", "/favicon.ico"}) {
+		t.Errorf("%s gave %v, want /assets/ and /favicon.ico",
+			rateLimitExemptPaths, cfg.RateLimitExemptPaths)
 	}
 }
 
-func TestRemoteLogSettingsAsSet(t *testing.T) {
+func TestPathPrefixNotStartingWithSlashStopsTheStart(t *testing.T) {
 	t.Parallel()
 
-	caFile := filepath.Join(t.TempDir(), "ca.pem")
+	_, err := config.FromEnvironment(
+		environment{rateLimitExemptPaths: "/favicon.ico,assets/"}.lookupEnv)
 
-	err := os.WriteFile(caFile, []byte(testCA), 0o600)
-	if err != nil {
-		t.Fatalf("write %s: %v", caFile, err)
-	}
-
-	cfg := fromEnvironment(t, environment{
-		logRemoteURL:       "syslog+tls://logs.example:6514",
-		logRemoteTLSCAFile: caFile,
-		logRemoteBuffer:    "500",
-		logRemoteFacility:  "daemon",
-		logRemoteAppName:   "fsn1app1/gitea",
-	})
-
-	roots := x509.NewCertPool()
-	roots.AppendCertsFromPEM([]byte(testCA))
-
-	if cfg.LogRemoteURL.String() != "syslog+tls://logs.example:6514" ||
-		!roots.Equal(cfg.LogRemoteTLSCAs) || cfg.LogRemoteBuffer != 500 ||
-		cfg.LogRemoteFacility != 3 || cfg.LogRemoteAppName != "fsn1app1/gitea" {
-		t.Errorf("remote log settings %v, %v, %d, %d and %q", cfg.LogRemoteURL,
-			cfg.LogRemoteTLSCAs, cfg.LogRemoteBuffer, cfg.LogRemoteFacility,
-			cfg.LogRemoteAppName)
-	}
-}
-
-func TestRemoteLogURLForms(t *testing.T) {
-	t.Parallel()
-
-	for _, value := range []string{
-		"syslog+udp://192.0.2.1:514",
-		"syslog+tcp://[2001:db8::1]:514",
-		"syslog+tls://logs.example:6514/",
-	} {
-		cfg := fromEnvironment(t, environment{logRemoteURL: value})
-		if cfg.LogRemoteURL.String() != value {
-			t.Errorf("%s read as %v", value, cfg.LogRemoteURL)
-		}
-	}
-
-	cfg := fromEnvironment(t, environment{logRemoteURL: ""})
-	if cfg.LogRemoteURL != nil {
-		t.Errorf("set but empty, %s read as %v", logRemoteURL, cfg.LogRemoteURL)
-	}
-}
-
-func TestRemoteLogFacilitiesByNumber(t *testing.T) {
-	t.Parallel()
-
-	for name, number := range map[string]int{
-		"kern": 0, "user": 1, "auth": 4, "authpriv": 10, "ftp": 11,
-		"local0": 16, "local5": 21, "local7": 23,
-	} {
-		cfg := fromEnvironment(t, environment{logRemoteFacility: name})
-		if cfg.LogRemoteFacility != number {
-			t.Errorf("%s read as %d, want %d", name, cfg.LogRemoteFacility, number)
-		}
-	}
-}
-
-func TestInvalidRemoteLogSettingStopsTheStart(t *testing.T) {
-	t.Parallel()
-
-	for _, tc := range []struct{ name, value string }{
-		{logRemoteURL, "logs.example:514"},
-		{logRemoteURL, "syslog://logs.example:514"},
-		{logRemoteURL, "http://logs.example:514"},
-		{logRemoteURL, "syslog+udp://logs.example"},
-		{logRemoteURL, "syslog+tcp://:514"},
-		{logRemoteURL, "syslog+tcp://logs.example:0"},
-		{logRemoteURL, "syslog+tls://logs.example:65536"},
-		{logRemoteURL, "syslog+tls://user@logs.example:6514"},
-		{logRemoteURL, "syslog+tcp://logs.example:514/app"},
-		{logRemoteURL, "syslog+tcp://logs.example:514?tls=1"},
-		{logRemoteTLSCAFile, "/nonexistent/ca.pem"},
-		{logRemoteBuffer, off}, {logRemoteBuffer, "0"}, {logRemoteBuffer, "10K"},
-		{logRemoteFacility, "local8"}, {logRemoteFacility, "LOCAL0"},
-		{logRemoteFacility, "16"}, {logRemoteFacility, ""},
-		{logRemoteAppName, ""}, {logRemoteAppName, "my app"},
-		{logRemoteAppName, "gitéa"}, {logRemoteAppName, strings.Repeat("a", 49)},
-	} {
-		_, err := config.FromEnvironment(environment{tc.name: tc.value}.lookupEnv)
-		if err == nil || !strings.HasPrefix(err.Error(), tc.name+": ") {
-			t.Errorf("%s=%q: error %v, want one naming it", tc.name, tc.value, err)
-		}
-	}
-}
-
-func TestRemoteLogCAFileWithoutCertificateStopsTheStart(t *testing.T) {
-	t.Parallel()
-
-	caFile := filepath.Join(t.TempDir(), "ca.pem")
-
-	err := os.WriteFile(caFile, []byte("not a certificate\n"), 0o600)
-	if err != nil {
-		t.Fatalf("write %s: %v", caFile, err)
-	}
-
-	_, err = config.FromEnvironment(environment{logRemoteTLSCAFile: caFile}.lookupEnv)
-
-	want := logRemoteTLSCAFile + `: "` + caFile + `" holds no PEM certificate`
+	want := rateLimitExemptPaths + `: "assets/" is not a path prefix ` +
+		`starting with /, such as /assets/`
 	if err == nil || err.Error() != want {
 		t.Errorf("error %v, want %s", err, want)
 	}
 }
 
+func TestInstanceNameAndLoggedHeadersAsSet(t *testing.T) {
+	t.Parallel()
+
+	cfg := fromEnvironment(t, environment{
+		instanceName:      "fsn1app1/gitea",
+		logRequestHeaders: " Accept , X-Custom",
+	})
+
+	if cfg.InstanceName != "fsn1app1/gitea" ||
+		!slices.Equal(cfg.LogRequestHeaders, []string{"accept", "x-custom"}) {
+		t.Errorf("%s is %q and %s gives %v", instanceName, cfg.InstanceName,
+			logRequestHeaders, cfg.LogRequestHeaders)
+	}
+}
+
 func TestCodeOnBothCountryListsStopsTheStart(t *testing.T) {
 	t.Parallel()
 
@@ -446,9 +357,7 @@ func TestInvalidValueStopsTheStart(t *testing.T) {
 	t.Parallel()
 
 	for _, tc := range []struct{ name, value string }{
-		{listenAddr, "8080"},
-		{listenAddr, ":http"},
-		{listenAddr, ":65536"},
+		{listenAddr, "8080"}, {listenAddr, ":http"}, {listenAddr, ":65536"},
 		{upstreamURL, "127.0.0.1:8081"},
 		{upstreamURL, "ftp://127.0.0.1:8081"},
 		{upstreamURL, "http://"},
@@ -466,8 +375,7 @@ func TestInvalidValueStopsTheStart(t *testing.T) {
 		{allowNets, "192.0.2.0/24,monitoring"},
 		{rateLimitExemptNets, "2001:db8::/129"},
 		{denyNets, "198.51.100.0/24,"},
-		{clientRequestTimeout, "60"},
-		{clientRequestTimeout, ""},
+		{clientRequestTimeout, "60"}, {clientRequestTimeout, ""},
 		{clientIdleTimeout, "0s"},
 		{clientIdleTimeout, "2 minutes"},
 		{clientResponseTimeout, "1y"},
@@ -484,8 +392,8 @@ func TestInvalidValueStopsTheStart(t *testing.T) {
 		{rateLimitPerMinute, "1K"},
 		{rateLimitPerHour, "0"},
 		{rateLimitPerHour, "1.5"},
-		{rateLimitPerDay, "-1"},
-		{rateLimitPerDay, "lots"},
+		{rateLimitPerDay, "-1"}, {rateLimitPerDay, "lots"},
+		{rateLimitExemptPaths, "/assets/,,/static/"},
 		{deniedCountries, "nk"},
 		{deniedCountries, "kp,,ir"},
 		{deniedCountries, "prk"},
@@ -508,6 +416,10 @@ func TestInvalidValueStopsTheStart(t *testing.T) {
 		{stateWriteDelay, off}, {stateWriteDelay, "0s"},
 		{stateCounterInterval, off}, {stateCounterInterval, "15"},
 		{metricsTopN, off}, {metricsTopN, "0"}, {metricsTopN, "-1"},
+		{logRequestHeaders, "accept,,origin"}, {logRequestHeaders, "accept;origin"},
+		{logRequestHeaders, "accept language"}, {logRequestHeaders, "x-foo:"},
+		{logRequestHeaders, "host"}, {logRequestHeaders, "accept,Host"},
+		{logRequestHeaders, "transfer-encoding"}, {logRequestHeaders, "TRANSFER-ENCODING"},
 	} {
 		t.Run(tc.name+"="+tc.value, func(t *testing.T) {
 			t.Parallel()
@@ -524,6 +436,27 @@ func TestInvalidValueStopsTheStart(t *testing.T) {
 	}
 }
 
+func TestHostOrTransferEncodingStopsTheStart(t *testing.T) {
+	t.Parallel()
+
+	// Only Host's message points to the field host.
+	for value, want := range map[string]string{
+		"Host": `"Host" is taken out of every request by Go's HTTP server, ` +
+			"so it can never be logged; the request's host is the field host",
+		"transfer-encoding": `"transfer-encoding" is taken out of every ` +
+			"request by Go's HTTP server, so it can never be logged",
+	} {
+		t.Run(value, func(t *testing.T) {
+			t.Parallel()
+
+			_, err := config.FromEnvironment(environment{logRequestHeaders: value}.lookupEnv)
+			if err == nil || err.Error() != logRequestHeaders+": "+want {
+				t.Errorf("error %v, want %s: %s", err, logRequestHeaders, want)
+			}
+		})
+	}
+}
+
 func TestShortTokenStopsTheStartWithoutShowingIt(t *testing.T) {
 	t.Parallel()
 
@@ -596,6 +529,7 @@ func TestLogsEachSettingWithItsValue(t *testing.T) {
 		rateLimitPerMinute:      "1000",
 		rateLimitPerHour:        "10000",
 		rateLimitPerDay:         "50000",
+		rateLimitExemptPaths:    "",
 		deniedCountries:         "",
 		allowedCountries:        "",
 		banResponse:             "403",
@@ -609,11 +543,8 @@ func TestLogsEachSettingWithItsValue(t *testing.T) {
 		stateCounterInterval:    "15m",
 		metricsToken:            "",
 		metricsTopN:             "50",
-		logRemoteURL:            "",
-		logRemoteTLSCAFile:      "",
-		logRemoteBuffer:         "10000",
-		logRemoteFacility:       "local0",
-		logRemoteAppName:        hostname,
+		instanceName:            hostname,
+		logRequestHeaders:       defaultLogRequestHeaders,
 	}
 	if !maps.Equal(line.Settings, want) {
 		t.Errorf("logged settings\n%v\nwant\n%v", line.Settings, want)

internal/metrics/metrics.go

@@ -13,7 +13,6 @@ import (
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"sneak.berlin/go/smallwebwaf/internal/bans"
 	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
-	"sneak.berlin/go/smallwebwaf/internal/remotelog"
 	"sneak.berlin/go/smallwebwaf/internal/requestlog"
 )
 
@@ -174,33 +173,6 @@ func (m *Metrics) AddBansAndClients(
 	)
 }
 
-// AddRemoteLog adds the metrics of sending the log lines to
-// SWWAF_LOG_REMOTE_URL, read from remote as the metrics are asked for: the
-// lines sent, those dropped, and those waiting in the buffer.
-func (m *Metrics) AddRemoteLog(remote *remotelog.Sender) {
-	m.registry.MustRegister(
-		prometheus.NewCounterFunc(prometheus.CounterOpts{
-			Name: "smallwebwaf_remote_log_lines_sent_total",
-			Help: "Log lines sent to SWWAF_LOG_REMOTE_URL.",
-		}, func() float64 {
-			return float64(remote.Sent())
-		}),
-		prometheus.NewCounterFunc(prometheus.CounterOpts{
-			Name: "smallwebwaf_remote_log_lines_dropped_total",
-			Help: "Log lines dropped: the oldest in a full buffer, and those " +
-				"whose sending failed.",
-		}, func() float64 {
-			return float64(remote.Dropped())
-		}),
-		prometheus.NewGaugeFunc(prometheus.GaugeOpts{
-			Name: "smallwebwaf_remote_log_buffer_depth",
-			Help: "Log lines in the buffer, waiting to be sent.",
-		}, func() float64 {
-			return float64(remote.Depth())
-		}),
-	)
-}
-
 // ServeHTTP answers with the metrics in the Prometheus text format.
 func (m *Metrics) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	m.handler.ServeHTTP(w, r)

internal/proxy/bans.go

@@ -30,14 +30,17 @@ func (rq *request) banned(now time.Time) bool {
 	return banned
 }
 
-// limitBroken counts the request for the rate limits at now, and reports
-// whether it takes the client over one. In enforce mode such a request
-// bans the client's netblock, and sets the client's counters back to
-// zero; in observe mode it does neither.
+// limitBroken counts the request for the rate limits at now, notes the
+// client's counts for the log line, and reports whether the request takes
+// the client over a limit. In enforce mode such a request bans the
+// client's netblock, and sets the client's counters back to zero; in
+// observe mode it does neither.
 func (rq *request) limitBroken(now time.Time) bool {
 	group := clientGroup(rq.client)
 
-	hit, over := rq.h.limiter.Count(group, now)
+	counts, hit, over := rq.h.limiter.Count(group, now)
+	rq.line.Counts = counts
+
 	if !over {
 		return false
 	}

internal/proxy/client.go

@@ -1,6 +1,7 @@
 package proxy
 
 import (
+	"crypto/rand"
 	"net/http"
 	"net/netip"
 	"slices"
@@ -48,6 +49,33 @@ func clientAddress(
 	return client
 }
 
+// requestIDHeader carries the request's id, from traefik and to the app.
+const requestIDHeader = "X-Request-ID"
+
+// requestID is the request's id: the one a trusted proxy sent, or a new
+// random one. A peer outside the trusted proxies did not come through
+// traefik, so the id it sends is its own claim, and is replaced.
+func requestID(r *http.Request, peerTrusted bool) string {
+	id := r.Header.Get(requestIDHeader)
+	if !peerTrusted || id == "" {
+		id = rand.Text()
+	}
+
+	return id
+}
+
+// scheme is how the client reached traefik, as a trusted proxy says in
+// X-Forwarded-Proto, or otherwise http, the only scheme smallwebwaf
+// serves.
+func scheme(r *http.Request, peerTrusted bool) string {
+	proto := r.Header.Get("X-Forwarded-Proto")
+	if !peerTrusted || proto == "" {
+		return "http"
+	}
+
+	return proto
+}
+
 // ipv6GroupPrefix is the length of the IPv6 netblock that is one client.
 const ipv6GroupPrefix = 64
 

internal/proxy/client_test.go

@@ -14,10 +14,14 @@ const (
 	appHost = "app.example"
 	// client is the client's address, as a proxy names it.
 	client = "203.0.113.9"
-	// forwardedFor is the header that lists the client and its proxies.
+	// forwardedFor is the header that lists the client and its proxies,
+	// and forwardedProto the one that gives the scheme the client used.
 	forwardedFor   = "X-Forwarded-For"
-	// secure is the scheme a client reached traefik with.
+	forwardedProto = "X-Forwarded-Proto"
+	// secure is the scheme a client reached traefik with, and plain the
+	// one smallwebwaf serves.
 	secure = "https"
+	plain  = "http"
 )
 
 // appHeaders is what the app tells about the headers it received.
@@ -67,11 +71,11 @@ func clientAddressCases() []clientAddressCase {
 	forged := http.Header{
 		forwardedFor:       {client},
 		"X-Forwarded-Host": {"forged.example"},
-		"X-Forwarded-Proto": {secure},
+		forwardedProto:     {secure},
 		"X-Real-Ip":        {client},
 	}
 	replaced := appHeaders{
-		ForwardedFor: localhost, ForwardedHost: appHost, ForwardedProto: "http",
+		ForwardedFor: localhost, ForwardedHost: appHost, ForwardedProto: plain,
 	}
 
 	return []clientAddressCase{{
@@ -89,7 +93,7 @@ func clientAddressCases() []clientAddressCase {
 		header: http.Header{
 			forwardedFor:       {"198.51.100.7, " + client + ", 10.0.0.2"},
 			"X-Forwarded-Host": {appHost},
-			"X-Forwarded-Proto": {secure},
+			forwardedProto:     {secure},
 			"X-Real-Ip":        {client},
 		},
 		wantClient: client,
@@ -138,7 +142,7 @@ func requestWithHeaders(
 			Host:           r.Host,
 			ForwardedFor:   r.Header.Get(forwardedFor),
 			ForwardedHost:  r.Header.Get("X-Forwarded-Host"),
-			ForwardedProto: r.Header.Get("X-Forwarded-Proto"),
+			ForwardedProto: r.Header.Get(forwardedProto),
 			RealIP:         r.Header.Get("X-Real-IP"),
 		})
 	})

internal/proxy/health_test.go

@@ -21,14 +21,18 @@ func TestHealthEndpointIsAnsweredBeforeAnyCheck(t *testing.T) {
 	// the last one would have it refused.
 	addr, out := startProxy(t, app.URL, map[string]string{rateLimitPerMinute: "1"})
 
-	const healthChecks = 3
+	const (
+		healthChecks = 3
+		contentType  = "text/plain; charset=utf-8"
+	)
 
 	for range healthChecks {
 		got := get(t, addr, proxy.HealthPath)
 		wantStatus(t, got, http.StatusOK)
 
-		if string(got.body) != "ok\n" {
-			t.Errorf("health endpoint answered %q, want ok", got.body)
+		if string(got.body) != "ok\n" || got.header.Get("Content-Type") != contentType {
+			t.Errorf("health endpoint answered %q with Content-Type %q, want ok "+
+				"with %q", got.body, got.header.Get("Content-Type"), contentType)
 		}
 	}
 
@@ -37,6 +41,11 @@ func TestHealthEndpointIsAnsweredBeforeAnyCheck(t *testing.T) {
 	lines := out.requestLines(t, healthChecks+1)
 	for _, line := range lines[:healthChecks] {
 		wantLine(t, line, http.StatusOK, requestlog.ActionAdmin)
+
+		if line.ResponseContentType != contentType {
+			t.Errorf("health check's log line has response_content_type %q, "+
+				"want %q", line.ResponseContentType, contentType)
+		}
 	}
 
 	wantLine(t, lines[healthChecks], http.StatusOK, requestlog.ActionForward)

internal/proxy/passthrough_test.go

@@ -6,6 +6,8 @@ import (
 	"errors"
 	"io"
 	"net/http"
+	"os"
+	"reflect"
 	"slices"
 	"strings"
 	"sync/atomic"
@@ -14,6 +16,7 @@ import (
 
 	"sneak.berlin/go/smallwebwaf/internal/config"
 	"sneak.berlin/go/smallwebwaf/internal/proxy"
+	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
 	"sneak.berlin/go/smallwebwaf/internal/requestlog"
 )
 
@@ -115,27 +118,34 @@ func wantAnswer(t *testing.T, got answer, body []byte) {
 	}
 }
 
-// wantRequestFields checks the log line's fields about the request.
+// wantRequestFields checks the log line's fields about the request. Its
+// time, its id and its timings are checked only for being there.
 func wantRequestFields(t *testing.T, line logLine, host string, sent, received int) {
 	t.Helper()
 
-	want := requestlog.Line{
-		Type: "request", Time: line.Time, ClientIP: localhost, PeerIP: localhost,
-		Method: http.MethodPatch, Host: host, Path: rawPath, Query: rawQuery,
-		Protocol: "HTTP/1.1", Status: http.StatusTeapot,
-		UpstreamStatus: http.StatusTeapot, RequestBytes: int64(sent),
+	hostname, _ := os.Hostname()
+
+	want := withTimings(line, requestlog.Line{
+		Type: requestType, Time: line.Time, Instance: hostname,
+		ClientIP: localhost, Method: http.MethodPatch, Scheme: plain, Host: host,
+		Path: rawPath, Query: rawQuery, Protocol: protocol,
+		Status: http.StatusTeapot, RequestBytes: int64(sent),
 		ResponseBytes: int64(received), UserAgent: "test-agent",
-		Action: requestlog.ActionForward, DurationTotal: line.DurationTotal,
-		DurationUpstreamTotal: line.DurationUpstreamTotal,
-	}
-	if line.Line != want {
+		RequestID: line.RequestID, PeerIP: localhost, ClientGroup: localhost + "/32",
+		ContentLength: int64(sent), ResponseContentType: "text/plain; charset=utf-8",
+		UpstreamStatus: http.StatusTeapot, Action: requestlog.ActionForward,
+		Counts: ratelimit.Counts{Minute: 1, Hour: 1, Day: 1},
+	})
+	if !reflect.DeepEqual(line.Line, want) {
 		t.Errorf("log line\n%+v\nwant\n%+v", line.Line, want)
 	}
 
 	_, err := time.Parse(time.RFC3339, line.Time)
-	if err != nil || line.DurationTotal <= 0 || line.DurationUpstreamTotal <= 0 {
-		t.Errorf("log line has time %q and durations %v and %v",
-			line.Time, line.DurationTotal, line.DurationUpstreamTotal)
+	if err != nil || line.RequestID == "" || line.DurationTotal <= 0 ||
+		line.DurationUpstreamTotal == nil || *line.DurationUpstreamTotal <= 0 {
+		t.Errorf("log line has time %q, request_id %q and durations %v and %v",
+			line.Time, line.RequestID, line.DurationTotal,
+			line.fields["duration_upstream_total"])
 	}
 }
 
@@ -371,8 +381,13 @@ func TestAnswers502WhenTheAppCannotBeReached(t *testing.T) {
 	addr, out := startProxy(t, "http://"+localhost+":1", nil)
 
 	wantStatus(t, get(t, addr, "/"), http.StatusBadGateway)
-	wantLine(t, out.requestLine(t), http.StatusBadGateway,
-		requestlog.ActionUpstreamError)
+
+	line := out.requestLine(t)
+	wantLine(t, line, http.StatusBadGateway, requestlog.ActionUpstreamError)
+
+	// There never was a connection to the app, nor an answer from it.
+	wantTimings(t, line, "duration_total", "duration_checks",
+		"duration_upstream_total")
 
 	logged := slices.ContainsFunc(out.lines(t), func(line map[string]any) bool {
 		return line["type"] == "process" && line["msg"] == "request to the app failed"

internal/proxy/proxy.go

@@ -160,6 +160,9 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	// a health checker is never refused. It does not ask the app.
 	if r.Method == http.MethodGet && r.URL.Path == HealthPath {
 		rq.line.Action = requestlog.ActionAdmin
+		// Set here rather than left to Go's server, which would set it only
+		// after the log line has taken the response's headers.
+		rq.out.Header().Set("Content-Type", "text/plain; charset=utf-8")
 		_, _ = io.WriteString(rq.out, "ok\n")
 
 		return
@@ -169,6 +172,8 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	defer rq.addToHistory()
 
 	refused := rq.check(r.Context())
+	rq.checked = time.Now()
+
 	if refused != nil {
 		rq.answer(*refused)
 

internal/proxy/proxy_test.go

@@ -35,6 +35,10 @@ const (
 	// localhost is where every test server listens, and so the address
 	// smallwebwaf sees each test's requests come from.
 	localhost = "127.0.0.1"
+	// requestType is the type that marks a request log line.
+	requestType = "request"
+	// protocol is the protocol of every test's requests.
+	protocol = "HTTP/1.1"
 )
 
 // shortTimeoutSetting is shortTimeout as a setting's value.
@@ -59,6 +63,7 @@ const (
 	denyNets                = "SWWAF_DENY_NETS"
 	rateLimitPerMinute      = "SWWAF_RATE_LIMIT_PER_MINUTE"
 	rateLimitPerDay         = "SWWAF_RATE_LIMIT_PER_DAY"
+	rateLimitExemptPaths    = "SWWAF_RATE_LIMIT_EXEMPT_PATHS"
 	deniedCountries         = "SWWAF_DENIED_COUNTRIES"
 	allowedCountries        = "SWWAF_EXCLUSIVELY_ALLOWED_COUNTRIES"
 	banResponse             = "SWWAF_BAN_RESPONSE"
@@ -67,6 +72,8 @@ const (
 	maxBanDuration          = "SWWAF_MAX_BAN_DURATION"
 	maxBans                 = "SWWAF_MAX_BANS"
 	banScopeV4Prefix        = "SWWAF_BAN_SCOPE_V4_PREFIX"
+	instanceName            = "SWWAF_INSTANCE_NAME"
+	logRequestHeaders       = "SWWAF_LOG_REQUEST_HEADERS"
 )
 
 // output collects what smallwebwaf writes on stdout.
@@ -83,6 +90,14 @@ func (o *output) Write(p []byte) (int, error) {
 	return o.buf.Write(p)
 }
 
+// text returns everything written so far.
+func (o *output) text() string {
+	o.mu.Lock()
+	defer o.mu.Unlock()
+
+	return o.buf.String()
+}
+
 // lines returns every line written so far, decoded.
 func (o *output) lines(t *testing.T) []map[string]any {
 	t.Helper()
@@ -122,7 +137,7 @@ func (o *output) requestLines(t *testing.T, count int) []logLine {
 		var found []logLine
 
 		for _, fields := range o.lines(t) {
-			if fields["type"] == "request" {
+			if fields["type"] == requestType {
 				found = append(found, decodeLine(t, fields))
 			}
 		}

internal/proxy/ratelimits_test.go

@@ -5,6 +5,8 @@ import (
 	"sync/atomic"
 	"testing"
 
+	"sneak.berlin/go/smallwebwaf/internal/lookup"
+	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
 	"sneak.berlin/go/smallwebwaf/internal/requestlog"
 )
 
@@ -69,3 +71,89 @@ func TestRateLimitRefusesBeforeTheApp(t *testing.T) {
 		t.Errorf("the app was called %d times, want 4", calls.Load())
 	}
 }
+
+func TestRateLimitExemptPathsAreNeitherCountedNorRefused(t *testing.T) {
+	t.Parallel()
+
+	const denied = "192.0.2.50" // in SWWAF_DENY_NETS
+
+	s, _, server := startWithClock(t, "", map[string]string{
+		rateLimitPerMinute:   "1",
+		rateLimitExemptPaths: "/assets/,/favicon.ico",
+		denyNets:             denied,
+		deniedCountries:      "kp",
+	})
+
+	// The answers are kept before the requests, so that none waits for
+	// GeoJS.
+	server.GeoJS.Load([]lookup.Answer{
+		keptAnswer(client, "DE"), keptAnswer(fromKP, "KP"),
+	})
+
+	// With a limit of one request a minute, the requests for paths under a
+	// prefix are not counted, so client's first request for / is within
+	// the limit; and once client has reached it, they are not refused.
+	s.request(client, "/assets/app.js", http.StatusOK, requestlog.ActionForward)
+	s.request(client, "/favicon.ico?v=2", http.StatusOK, requestlog.ActionForward)
+	s.get(client, http.StatusOK, requestlog.ActionForward)
+
+	line := s.request(client, "/assets/app.js", http.StatusOK, requestlog.ActionForward)
+	if line.LimitHit != "" || line.Counts != (ratelimit.Counts{}) {
+		t.Errorf("log line has limit_hit %q and counts %+v, want neither",
+			line.LimitHit, line.Counts)
+	}
+
+	// A path outside every prefix is counted: /assets is not under
+	// /assets/, and breaks the limit.
+	s.request(client, "/assets", http.StatusForbidden, requestlog.ActionRateLimited)
+
+	// A ban, SWWAF_DENY_NETS and the country lists still refuse a path
+	// under a prefix.
+	s.request(client, "/assets/app.js", http.StatusForbidden, requestlog.ActionBanned)
+	s.request(denied, "/assets/app.js", http.StatusForbidden, requestlog.ActionDenied)
+	s.request(fromKP, "/assets/app.js",
+		http.StatusForbidden, requestlog.ActionCountryDenied)
+}
+
+func TestRateLimitCountsPathsThatAreNotExempt(t *testing.T) {
+	t.Parallel()
+
+	for _, sent := range []string{
+		// A prefix matches only at the start of the path.
+		"/static/assets/app.js",
+		// A prefix matches the path as sent: a router that matches the
+		// path as received does not take /%61ssets/x for a path under
+		// /assets/.
+		"/%61ssets/x",
+		// .. once percent-decoded: an app may act on these as /login, the
+		// last as a path under /sneak/app/ or as /assets/x.
+		"/assets/../login",
+		"/assets/%2e%2e/login",
+		"/assets/..%2Flogin",
+		"/assets/..;/login",
+		"/sneak/app/src/branch/main/..%2F..%2F..%2F..%2F..%2F..%2Fassets/x",
+		// Not under /assets/ as sent: Go's router takes /assets%2Fx for one
+		// path segment, not a path under /assets/.
+		"/assets%2Fx",
+		"/assets%2fx",
+		// Under /assets/ as sent, but holding an encoded slash, in either
+		// case, or a backslash: never exempt, whatever the prefix.
+		"/assets/x%2Fy",
+		"/assets/x%2fy",
+		`/assets/x\y`,
+	} {
+		t.Run(sent, func(t *testing.T) {
+			t.Parallel()
+
+			s, _, _ := startWithClock(t, "", map[string]string{
+				rateLimitPerMinute:   "1",
+				rateLimitExemptPaths: "/assets/",
+			})
+
+			// Counted, the second request breaks the limit of one request
+			// a minute.
+			s.request(client, sent, http.StatusOK, requestlog.ActionForward)
+			s.request(client, sent, http.StatusForbidden, requestlog.ActionRateLimited)
+		})
+	}
+}

internal/proxy/request.go

@@ -7,7 +7,10 @@ import (
 	"net/http/httptrace"
 	"net/http/httputil"
 	"net/netip"
+	"net/url"
 	"os"
+	"slices"
+	"strings"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -46,7 +49,9 @@ type request struct {
 	peer        netip.Addr
 	peerTrusted bool
 	start       time.Time
-	// upstreamStart is when the request was handed to the app.
+	// checked is when the checks were done, and upstreamStart when the
+	// request was handed to the app.
+	checked       time.Time
 	upstreamStart time.Time
 	// cancel ends the request to the app.
 	cancel context.CancelFunc
@@ -56,26 +61,34 @@ type request struct {
 	complete bool
 
 	// mu guards what follows. The timeouts run on goroutines of their
-	// own, and the transport starts and stops them from its own; once
-	// timersStopped is set, none of them acts any more.
+	// own, and the transport starts and stops them, and notes the times
+	// below, from its own; once timersStopped is set, none of the timeouts
+	// acts any more.
 	mu                    sync.Mutex
 	timersStopped         bool
 	clientRequestTimer    *time.Timer
 	upstreamRequestTimer  *time.Timer
 	upstreamResponseTimer *time.Timer
-	// requestSent is when the app had been sent the whole request.
+	// connected is when there was a connection to the app, requestSent
+	// when the app had been sent the whole request, and answerStarted
+	// when the first byte of its answer arrived.
+	connected     time.Time
 	requestSent   time.Time
+	answerStarted time.Time
 }
 
 // newRequest starts handling r: it notes the time, counts the request as
-// under way, and works out the client.
+// under way, works out the client, and starts the log line with what is
+// known of the request.
 func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
 	h.metrics.RequestStarted()
 
 	start := time.Now()
 	peer := peerAddress(r)
 	trusted := h.config.TrustedProxies
-	client := clientAddress(peer, r.Header.Values("X-Forwarded-For"), trusted)
+	peerTrusted := isInside(peer, trusted)
+	forwardedFor := r.Header.Values("X-Forwarded-For")
+	client := clientAddress(peer, forwardedFor, trusted)
 
 	rq := &request{
 		h:           h,
@@ -84,22 +97,37 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
 		out:         &responseWriter{ResponseWriter: w},
 		client:      client,
 		peer:        peer,
-		peerTrusted: isInside(peer, trusted),
+		peerTrusted: peerTrusted,
 		start:       start,
 		line: requestlog.Line{
 			Time:             requestlog.FormatTime(start),
+			Instance:         h.config.InstanceName,
 			ClientIP:         client.String(),
-			PeerIP:    peer.String(),
 			Method:           r.Method,
+			Scheme:           scheme(r, peerTrusted),
 			Host:             r.Host,
 			Path:             r.URL.EscapedPath(),
 			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:      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.
+	if r.ContentLength > 0 {
+		rq.line.ContentLength = r.ContentLength
+	}
+
 	if r.Body != http.NoBody {
 		rq.body = &requestBody{body: limitBody(r.Body, h.config.RequestMaxBytes), rq: rq}
 	}
@@ -107,6 +135,27 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
 	return rq
 }
 
+// requestHeaders returns the headers of r that names lists, by name in
+// lower case, each with its values joined by ", ". Authorization, Cookie
+// and Set-Cookie are never among them, whatever names says.
+func requestHeaders(r *http.Request, names []string) map[string]string {
+	headers := map[string]string{}
+
+	for _, name := range names {
+		switch name {
+		case "authorization", "cookie", "set-cookie":
+			continue
+		}
+
+		values := r.Header.Values(name)
+		if len(values) > 0 {
+			headers[name] = strings.Join(values, ", ")
+		}
+	}
+
+	return headers
+}
+
 // check is the one place where a request can be refused once its client
 // is known, before its body is read or anything reaches the app. It
 // returns nil to let the request through. The checks of checkClient come
@@ -145,7 +194,8 @@ func (rq *request) check(ctx context.Context) *refusal {
 // client either refuses is not looked up, and then the country lists; a
 // request any of them refuses is not counted for the rate limits. Then
 // come the rate limits, unless the client is in
-// SWWAF_RATE_LIMIT_EXEMPT_NETS, so that every other request is counted.
+// SWWAF_RATE_LIMIT_EXEMPT_NETS or the request's path is exempt under
+// SWWAF_RATE_LIMIT_EXEMPT_PATHS, so that every other request is counted.
 // ctx is the request's own context.
 func (rq *request) checkClient(ctx context.Context) string {
 	cfg := rq.h.config
@@ -167,13 +217,39 @@ func (rq *request) checkClient(ctx context.Context) string {
 		return requestlog.ActionCountryDenied
 	}
 
-	if !isInside(rq.client, cfg.RateLimitExemptNets) && rq.limitBroken(now) {
+	exempt := isInside(rq.client, cfg.RateLimitExemptNets) ||
+		pathExempt(rq.in.URL, cfg.RateLimitExemptPaths)
+	if !exempt && rq.limitBroken(now) {
 		return requestlog.ActionRateLimited
 	}
 
 	return ""
 }
 
+// pathExempt reports whether the rate limits leave out a request for u
+// because of SWWAF_RATE_LIMIT_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 app whose
+// router matches the path as received. A request whose decoded path
+// contains .. anywhere or a backslash, or whose path as sent holds an
+// 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 {
+	decoded := u.Path
+	// EscapedPath is the path as the app receives it, not decoded.
+	sent := u.EscapedPath()
+
+	if strings.Contains(decoded, "..") || strings.Contains(decoded, `\`) ||
+		strings.Contains(strings.ToLower(sent), "%2f") {
+		return false
+	}
+
+	return slices.ContainsFunc(prefixes, func(prefix string) bool {
+		return strings.HasPrefix(sent, prefix)
+	})
+}
+
 // forward passes the request to the app and the app's answer back. ctx
 // is the request's own context.
 func (rq *request) forward(ctx context.Context) {
@@ -182,7 +258,9 @@ func (rq *request) forward(ctx context.Context) {
 
 	rq.cancel = cancel
 	ctx = httptrace.WithClientTrace(ctx, &httptrace.ClientTrace{
+		GotConn:              rq.gotConn,
 		WroteRequest:         rq.wroteRequest,
+		GotFirstResponseByte: rq.gotFirstResponseByte,
 	})
 
 	out := rq.in.WithContext(ctx)
@@ -205,7 +283,8 @@ func (rq *request) forward(ctx context.Context) {
 }
 
 // rewrite makes the request the app receives: the client's request,
-// unchanged, sent to SWWAF_UPSTREAM_URL, with the forwarded headers set.
+// unchanged, sent to SWWAF_UPSTREAM_URL, with the forwarded headers and
+// the request's id set.
 func (rq *request) rewrite(pr *httputil.ProxyRequest) {
 	upstream := rq.h.config.UpstreamURL
 	pr.Out.URL.Scheme = upstream.Scheme
@@ -214,6 +293,7 @@ func (rq *request) rewrite(pr *httputil.ProxyRequest) {
 	// the query as the client sent it.
 	pr.Out.URL.RawQuery = pr.In.URL.RawQuery
 	setForwardedHeaders(pr.In, pr.Out, rq.peer, rq.peerTrusted)
+	pr.Out.Header.Set(requestIDHeader, rq.line.RequestID)
 }
 
 // modifyResponse looks at the app's answer before ReverseProxy passes it
@@ -227,6 +307,7 @@ func (rq *request) modifyResponse(res *http.Response) error {
 		// connection it takes over, not through rq.out.
 		rq.stopTimers()
 		rq.out.status = res.StatusCode
+		rq.line.Websocket = true
 
 		return nil
 	}
@@ -322,6 +403,10 @@ func (rq *request) finish() {
 	line := &rq.line
 	line.Status = rq.out.status
 	line.ResponseBytes = rq.out.bytes
+	header := rq.out.Header()
+	line.ResponseContentType = header.Get("Content-Type")
+	line.CacheControl = header.Get("Cache-Control")
+	line.Location = header.Get("Location")
 
 	if rq.body != nil {
 		line.RequestBytes = rq.body.bytes.Load()
@@ -346,12 +431,18 @@ func (rq *request) finish() {
 	now := time.Now()
 	duration := now.Sub(rq.start)
 	line.DurationTotal = requestlog.Milliseconds(duration)
+	line.DurationChecks = timing(rq.start, rq.checked)
 
 	var upstreamDuration time.Duration
 
 	if !rq.upstreamStart.IsZero() {
 		upstreamDuration = now.Sub(rq.upstreamStart)
-		line.DurationUpstreamTotal = requestlog.Milliseconds(upstreamDuration)
+		line.DurationUpstreamTotal = new(requestlog.Milliseconds(upstreamDuration))
+
+		rq.mu.Lock()
+		line.DurationUpstreamConnect = timing(rq.upstreamStart, rq.connected)
+		line.DurationUpstreamFirstByte = timing(rq.upstreamStart, rq.answerStarted)
+		rq.mu.Unlock()
 	}
 
 	// Counted before the log line is written, so that the metrics count
@@ -364,6 +455,17 @@ func (rq *request) finish() {
 	}
 }
 
+// timing is the time from start to end in milliseconds, for one of the
+// log line's timings, or nil when end is zero: what it times never
+// happened.
+func timing(start, end time.Time) *float64 {
+	if end.IsZero() {
+		return nil
+	}
+
+	return new(requestlog.Milliseconds(end.Sub(start)))
+}
+
 // addToHistory adds the request, which has ended, to its client's
 // history.
 func (rq *request) addToHistory() {
@@ -473,6 +575,24 @@ func (rq *request) bodyReceived() {
 	stopTimer(rq.clientRequestTimer)
 }
 
+// gotConn is called once there is a connection to the app, a new one or
+// one kept open from an earlier request.
+func (rq *request) gotConn(httptrace.GotConnInfo) {
+	rq.mu.Lock()
+	defer rq.mu.Unlock()
+
+	rq.connected = time.Now()
+}
+
+// gotFirstResponseByte is called once the first byte of the app's answer
+// has arrived.
+func (rq *request) gotFirstResponseByte() {
+	rq.mu.Lock()
+	defer rq.mu.Unlock()
+
+	rq.answerStarted = time.Now()
+}
+
 // wroteRequest is called once the app has been sent the whole request:
 // the request timeouts end and SWWAF_UPSTREAM_RESPONSE_TIMEOUT starts.
 func (rq *request) wroteRequest(info httptrace.WroteRequestInfo) {

internal/proxy/requestlog_test.go

@@ -0,0 +1,368 @@
+package proxy_test
+
+import (
+	"io"
+	"maps"
+	"math"
+	"net/http"
+	"reflect"
+	"slices"
+	"strings"
+	"testing"
+	"time"
+
+	"sneak.berlin/go/smallwebwaf/internal/proxy"
+	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
+	"sneak.berlin/go/smallwebwaf/internal/requestlog"
+)
+
+const (
+	// requestIDHeader carries the request's id.
+	requestIDHeader = "X-Request-ID"
+	// instance is the SWWAF_INSTANCE_NAME a test sets.
+	instance = "fsn1app1/gitea"
+	// ipv6Client is a client on IPv6, and ipv6Group the netblock the rate
+	// limits count it as.
+	ipv6Client = "2001:db8::7"
+	ipv6Group  = "2001:db8::/64"
+)
+
+func TestLogLineHasEachFieldWhereItApplies(t *testing.T) {
+	t.Parallel()
+
+	received := make(chan string, 2) // the request ids the app received
+	app := startApp(t, func(w http.ResponseWriter, r *http.Request) {
+		received <- r.Header.Get(requestIDHeader)
+
+		_, _ = io.Copy(io.Discard, r.Body)
+
+		if r.URL.Path != "/full" {
+			w.WriteHeader(http.StatusNoContent)
+
+			return
+		}
+
+		w.Header().Set("Content-Type", "text/html")
+		w.Header().Set("Cache-Control", "no-store")
+		w.Header().Set("Location", "/elsewhere")
+		w.WriteHeader(http.StatusFound)
+		_, _ = io.WriteString(w, "moved")
+	})
+	addr, out := startProxy(t, app.URL, map[string]string{
+		trustedProxies:      trustLocalhost,
+		rateLimitExemptNets: localhost,
+		instanceName:        instance,
+		logRequestHeaders:   "Accept,x-custom,Authorization,cookie,SET-COOKIE",
+	})
+
+	// This request comes from ipv6Client through a trusted proxy, with a
+	// body and each header the log line looks at, and is answered with a
+	// redirect.
+	conn := dial(t, addr)
+	send(t, conn, "POST /full HTTP/1.1\r\nHost: "+appHost+"\r\n"+
+		forwardedFor+": 198.51.100.7, "+ipv6Client+"\r\n"+
+		forwardedProto+": "+secure+"\r\n"+requestIDHeader+": from-traefik\r\n"+
+		"Content-Type: application/x-www-form-urlencoded\r\nContent-Length: 3\r\n"+
+		"Accept: text/html\r\nX-Custom: one\r\nX-Custom: two\r\n"+
+		"Authorization: Bearer secret-token\r\nCookie: session=secret-cookie\r\n"+
+		"Set-Cookie: secret-set-cookie\r\n\r\na=b")
+	wantStatus(t, readResponse(t, conn), http.StatusFound)
+
+	// A request's log line can come after its answer: each is waited for
+	// before the next request, so that the lines are in order.
+	full := out.requestLines(t, 1)[0]
+
+	// This one comes from 127.0.0.1, which the rate limits do not count,
+	// with a body of 4 bytes whose length it does not announce, so that its
+	// request_bytes is not its content_length, and no header the log line
+	// looks at, and is answered with 204 and no header.
+	conn = dial(t, addr)
+	send(t, conn, "POST /bare HTTP/1.1\r\nHost: "+appHost+"\r\n"+
+		"Transfer-Encoding: chunked\r\n\r\n4\r\nbody\r\n0\r\n\r\n")
+	wantStatus(t, readResponse(t, conn), http.StatusNoContent)
+
+	bare := out.requestLines(t, 2)[1]
+
+	wantFullLine(t, full)
+	wantBareLine(t, bare)
+
+	for _, line := range []logLine{full, bare} {
+		got := <-received
+		if got != line.RequestID {
+			t.Errorf("the app received request id %q, the log line has %q",
+				got, line.RequestID)
+		}
+	}
+
+	if strings.Contains(out.text(), "secret") {
+		t.Errorf("a value of Authorization, Cookie or Set-Cookie is logged:\n%s",
+			out.text())
+	}
+}
+
+// wantFullLine checks the log line of the request with every header the
+// line looks at. Its timings are checked by TestTimingsAreInOrder.
+func wantFullLine(t *testing.T, line logLine) {
+	t.Helper()
+
+	headers := map[string]string{"accept": "text/html", "x-custom": "one, two"}
+
+	want := withTimings(line, requestlog.Line{
+		Type: requestType, Time: line.Time, Instance: instance,
+		ClientIP: ipv6Client, Method: http.MethodPost, Scheme: secure,
+		Host: appHost, Path: "/full", Protocol: protocol,
+		Status: http.StatusFound, RequestBytes: 3, ResponseBytes: 5,
+		RequestID: "from-traefik", PeerIP: localhost,
+		ForwardedFor: "198.51.100.7, " + ipv6Client, ClientGroup: ipv6Group,
+		ContentType: "application/x-www-form-urlencoded", ContentLength: 3,
+		RequestHeaders: headers, HasAuthorization: true, HasCookie: true,
+		ResponseContentType: "text/html", UpstreamStatus: http.StatusFound,
+		CacheControl: "no-store", Location: "/elsewhere",
+		Action: requestlog.ActionForward,
+		Counts: ratelimit.Counts{Minute: 1, Hour: 1, Day: 1},
+	})
+	if !reflect.DeepEqual(line.Line, want) {
+		t.Errorf("log line\n%+v\nwant\n%+v", line.Line, want)
+	}
+}
+
+// wantBareLine checks the log line of the request with none of them, and
+// that the fields that do not apply to it are left out.
+func wantBareLine(t *testing.T, line logLine) {
+	t.Helper()
+
+	want := withTimings(line, requestlog.Line{
+		Type: requestType, Time: line.Time, Instance: instance,
+		ClientIP: localhost, Method: http.MethodPost, Scheme: plain,
+		Host: appHost, Path: "/bare", Protocol: protocol,
+		Status: http.StatusNoContent, RequestBytes: 4, RequestID: line.RequestID,
+		PeerIP: localhost, ClientGroup: localhost + "/32",
+		UpstreamStatus: http.StatusNoContent, Action: requestlog.ActionForward,
+	})
+	if !reflect.DeepEqual(line.Line, want) || line.RequestID == "" {
+		t.Errorf("log line\n%+v\nwant\n%+v, with a request id", line.Line, want)
+	}
+
+	for _, name := range []string{
+		"forwarded_for", "content_type", "content_length", "request_headers",
+		"has_authorization", "has_cookie", "websocket", "response_content_type",
+		"cache_control", "location", "counts",
+	} {
+		_, present := line.fields[name]
+		if present {
+			t.Errorf("log line has %s, which does not apply", name)
+		}
+	}
+}
+
+// withTimings returns want with the timings of line.
+func withTimings(line logLine, want requestlog.Line) requestlog.Line {
+	want.DurationTotal = line.DurationTotal
+	want.DurationChecks = line.DurationChecks
+	want.DurationUpstreamConnect = line.DurationUpstreamConnect
+	want.DurationUpstreamFirstByte = line.DurationUpstreamFirstByte
+	want.DurationUpstreamTotal = line.DurationUpstreamTotal
+
+	return want
+}
+
+func TestHasAuthorizationAndHasCookieEachComeFromTheirOwnHeader(t *testing.T) {
+	t.Parallel()
+
+	const hasAuthorization, hasCookie = "has_authorization", "has_cookie"
+
+	for _, tc := range []struct{ header, field, other string }{
+		{"Authorization", hasAuthorization, hasCookie},
+		{"Cookie", hasCookie, hasAuthorization},
+	} {
+		t.Run("only "+tc.header, func(t *testing.T) {
+			t.Parallel()
+
+			app := startApp(t, func(http.ResponseWriter, *http.Request) {})
+			addr, out := startProxy(t, app.URL, nil)
+
+			req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
+			req.Header.Set(tc.header, "secret")
+			wantStatus(t, do(t, req), http.StatusOK)
+
+			line := out.requestLine(t)
+
+			_, otherPresent := line.fields[tc.other]
+			if line.fields[tc.field] != true || otherPresent {
+				t.Errorf("log line has %s %v and %s %v, want true and none",
+					tc.field, line.fields[tc.field], tc.other, line.fields[tc.other])
+			}
+		})
+	}
+}
+
+func TestRequestIDAndSchemeComeOnlyFromATrustedProxy(t *testing.T) {
+	t.Parallel()
+
+	const sentID = "from-traefik"
+
+	sent := http.Header{requestIDHeader: {sentID}, forwardedProto: {secure}}
+	trusted := map[string]string{trustedProxies: trustLocalhost}
+
+	for _, tc := range []struct {
+		name   string
+		env    map[string]string
+		header http.Header
+		// wantID is the request id logged, "" for a new one.
+		wantID, wantScheme string
+	}{
+		{"a trusted proxy's are kept", trusted, sent, sentID, secure},
+		{"without them, the id is new and the scheme http", trusted, nil, "", plain},
+		{"another peer's are replaced", nil, sent, "", plain},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+
+			received := make(chan string, 2)
+			app := startApp(t, func(_ http.ResponseWriter, r *http.Request) {
+				received <- r.Header.Get(requestIDHeader)
+			})
+			addr, out := startProxy(t, app.URL, tc.env)
+
+			// Two requests, so that two new ids can be told apart.
+			ids := make([]string, 0, 2)
+
+			for i := range 2 {
+				req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
+				maps.Copy(req.Header, tc.header)
+				wantStatus(t, do(t, req), http.StatusOK)
+
+				line := out.requestLines(t, i+1)[i]
+				ids = append(ids, line.RequestID)
+
+				got := <-received
+				if line.RequestID != got || line.Scheme != tc.wantScheme {
+					t.Errorf("log line has request_id %q and scheme %q, and the "+
+						"app received id %q; want the same id and scheme %q",
+						line.RequestID, line.Scheme, got, tc.wantScheme)
+				}
+			}
+
+			switch {
+			case tc.wantID != "" && (ids[0] != tc.wantID || ids[1] != tc.wantID):
+				t.Errorf("request ids %q, want %q", ids, tc.wantID)
+			case tc.wantID == "" && (slices.Contains(ids, sentID) ||
+				slices.Contains(ids, "") || ids[0] == ids[1]):
+				t.Errorf("request ids %q, want two new ones", ids)
+			}
+		})
+	}
+}
+
+func TestTimingsAreInOrder(t *testing.T) {
+	t.Parallel()
+
+	const denied = "192.0.2.50" // in SWWAF_DENY_NETS
+
+	app := startApp(t, func(w http.ResponseWriter, _ *http.Request) {
+		// The pauses set the times apart; a hold-up of the test only
+		// lengthens them.
+		time.Sleep(time.Millisecond)
+		w.WriteHeader(http.StatusOK)
+		_ = http.NewResponseController(w).Flush()
+
+		time.Sleep(time.Millisecond)
+
+		_, _ = io.WriteString(w, "done")
+	})
+	addr, out := startProxy(t, app.URL, map[string]string{
+		trustedProxies: trustLocalhost,
+		denyNets:       denied,
+	})
+
+	// Each log line is waited for before the next request, so that the
+	// lines are in order.
+	wantStatus(t, get(t, addr, "/"), http.StatusOK)
+	forwarded := out.requestLines(t, 1)[0]
+
+	req := newRequest(t, http.MethodGet, addr, "/", http.NoBody)
+	req.Header.Set(forwardedFor, denied)
+	wantStatus(t, do(t, req), http.StatusForbidden)
+	refused := out.requestLines(t, 2)[1]
+
+	wantStatus(t, get(t, addr, proxy.HealthPath), http.StatusOK)
+	health := out.requestLines(t, 3)[2]
+
+	// A request passed to the app has every timing; one refused, none of
+	// the app's; the health check, which runs no check, only the total.
+	wantTimings(t, forwarded, "duration_total", "duration_checks",
+		"duration_upstream_connect", "duration_upstream_first_byte",
+		"duration_upstream_total")
+	wantTimings(t, refused, "duration_total", "duration_checks")
+	wantTimings(t, health, "duration_total")
+
+	if t.Failed() {
+		return
+	}
+
+	// In whole microseconds, as they are logged, so that the sum below is
+	// exact.
+	total := microseconds(forwarded.DurationTotal)
+	checks := microseconds(*forwarded.DurationChecks)
+	connect := microseconds(*forwarded.DurationUpstreamConnect)
+	firstByte := microseconds(*forwarded.DurationUpstreamFirstByte)
+	upstream := microseconds(*forwarded.DurationUpstreamTotal)
+
+	// The checks end before the request is handed to the app, and the
+	// connection comes before the answer, which the app ends after a
+	// pause.
+	if checks+upstream > total || connect >= firstByte || firstByte >= upstream {
+		t.Errorf("timings in microseconds: total %d, checks %d, connect %d, "+
+			"first byte %d, upstream total %d", total, checks, connect, firstByte,
+			upstream)
+	}
+
+	if *refused.DurationChecks > refused.DurationTotal {
+		t.Errorf("refused request's checks took %v of %v milliseconds",
+			*refused.DurationChecks, refused.DurationTotal)
+	}
+}
+
+// wantTimings checks that the timings named are the only ones line has.
+func wantTimings(t *testing.T, line logLine, want ...string) {
+	t.Helper()
+
+	var got []string
+
+	for name := range line.fields {
+		if strings.HasPrefix(name, "duration_") {
+			got = append(got, name)
+		}
+	}
+
+	slices.Sort(got)
+	slices.Sort(want)
+
+	if !slices.Equal(got, want) {
+		t.Errorf("log line of %s has timings %v, want %v", line.Path, got, want)
+	}
+}
+
+// microseconds is a timing in whole microseconds.
+func microseconds(milliseconds float64) int64 {
+	return int64(math.Round(milliseconds * 1000))
+}
+
+func TestLogsAnUpgradedConnection(t *testing.T) {
+	t.Parallel()
+
+	app := startApp(t, echoAfterUpgrade)
+	addr, out := startProxy(t, app.URL, nil)
+
+	conn := dial(t, addr)
+	send(t, conn, "GET /socket HTTP/1.1\r\nHost: app\r\n"+
+		"Connection: Upgrade\r\nUpgrade: websocket\r\n\r\n")
+	wantStatus(t, readResponse(t, conn), http.StatusSwitchingProtocols)
+
+	_ = conn.Close()
+
+	line := out.requestLine(t)
+	if line.fields["websocket"] != true {
+		t.Errorf("log line has websocket %v, want true", line.fields["websocket"])
+	}
+}

internal/ratelimit/ratelimit.go

@@ -149,26 +149,39 @@ type Hit struct {
 	Requests float64
 }
 
+// Counts are a client's requests in the minute, the hour and the day that
+// end at a request, that request included.
+type Counts struct {
+	Minute float64 `json:"minute"`
+	Hour   float64 `json:"hour"`
+	Day    float64 `json:"day"`
+}
+
 // Count counts a request from client at now, in every window, whether or
-// not it is refused. It reports whether the request takes the client over
-// a limit, and the window whose limit it goes over, the shortest if it is
-// over several.
-func (l *Limiter) Count(client netip.Prefix, now time.Time) (Hit, bool) {
+// not it is refused, and returns the client's requests in each window. It
+// reports whether the request takes the client over a limit, and the
+// window whose limit it goes over, the shortest if it is over several.
+func (l *Limiter) Count(client netip.Prefix, now time.Time) (Counts, Hit, bool) {
 	l.mu.Lock()
 	defer l.mu.Unlock()
 
-	var hit Hit
+	var (
+		requests [3]float64
+		hit      Hit
+	)
 
 	for i, b := range l.get(client).buckets() {
 		w := l.windows[i]
 
-		requests := b.add(now, w.length)
-		if hit.Window == "" && w.limit > 0 && requests > float64(w.limit) {
-			hit = Hit{Window: w.name, Limit: w.limit, Requests: requests}
+		requests[i] = b.add(now, w.length)
+		if hit.Window == "" && w.limit > 0 && requests[i] > float64(w.limit) {
+			hit = Hit{Window: w.name, Limit: w.limit, Requests: requests[i]}
 		}
 	}
 
-	return hit, hit.Window != ""
+	counts := Counts{Minute: requests[0], Hour: requests[1], Day: requests[2]}
+
+	return counts, hit, hit.Window != ""
 }
 
 // Reset sets client's counts in every window back to zero. Its history

internal/ratelimit/ratelimit_test.go

@@ -62,14 +62,14 @@ func TestHitGivesTheLimitAndTheRequestsCounted(t *testing.T) {
 	start := midnight()
 
 	for range limit {
-		_, over := limiter.Count(client, start)
+		_, _, over := limiter.Count(client, start)
 		if over {
 			t.Fatal("a request within the limit is over it")
 		}
 	}
 
 	// Over both limits; the minute's is named, with the four requests.
-	hit, over := limiter.Count(client, start)
+	_, hit, over := limiter.Count(client, start)
 
 	want := ratelimit.Hit{Window: minute, Limit: limit, Requests: limit + 1}
 	if !over || hit != want {
@@ -78,6 +78,29 @@ func TestHitGivesTheLimitAndTheRequestsCounted(t *testing.T) {
 	}
 }
 
+func TestCountGivesTheRequestsInEachWindow(t *testing.T) {
+	t.Parallel()
+
+	limiter := ratelimit.New(ratelimit.Limits{})
+	client := netip.MustParsePrefix("203.0.113.9/32")
+	start := midnight()
+
+	for range 3 {
+		limiter.Count(client, start)
+	}
+
+	// A quarter into the next hour, the minute has only this request. The
+	// hour still covers three quarters of the bucket before, with its three
+	// requests, which count 2.25, and this one: 3.25. The day covers all
+	// four.
+	counts, _, _ := limiter.Count(client, start.Add(time.Hour+time.Hour/4))
+
+	want := ratelimit.Counts{Minute: 1, Hour: 3.25, Day: 4}
+	if counts != want {
+		t.Errorf("counts %+v, want %+v", counts, want)
+	}
+}
+
 func TestResetSetsTheCountsBackToZero(t *testing.T) {
 	t.Parallel()
 
@@ -238,7 +261,7 @@ func wantCount(
 ) {
 	t.Helper()
 
-	hit, _ := limiter.Count(client, now)
+	_, hit, _ := limiter.Count(client, now)
 	if hit.Window != want {
 		t.Errorf("request from %s at %s is over %q, want %q",
 			client, now.Format(time.RFC3339), hit.Window, want)

internal/remotelog/remotelog.go

@@ -1,296 +0,0 @@
-// Package remotelog sends the lines smallwebwaf writes on stdout to the
-// remote log endpoint, SWWAF_LOG_REMOTE_URL, as the "Request log" section
-// of SPEC.md describes: each line as the message of an RFC 5424 syslog
-// record, over UDP, TCP or TLS. Lines wait in a bounded buffer, so a slow
-// or unreachable endpoint never holds up a request or stdout.
-package remotelog
-
-import (
-	"bytes"
-	"context"
-	"crypto/tls"
-	"crypto/x509"
-	"fmt"
-	"log/slog"
-	"net"
-	"net/url"
-	"os"
-	"strconv"
-	"sync/atomic"
-	"time"
-
-	"sneak.berlin/go/smallwebwaf/internal/requestlog"
-)
-
-// The forms of SWWAF_LOG_REMOTE_URL, by its scheme.
-const (
-	SchemeUDP = "syslog+udp"
-	SchemeTCP = "syslog+tcp"
-	SchemeTLS = "syslog+tls"
-)
-
-// A record's priority is the number of its facility times the number of
-// severities there are, plus the number of its severity. Every record's
-// severity is informational.
-const (
-	severities    = 8
-	informational = 6
-)
-
-const (
-	// dialTimeout bounds connecting to the endpoint, the TLS handshake
-	// included.
-	dialTimeout = 10 * time.Second
-	// After a failed attempt to connect, the next is made a second later,
-	// and retryDelayFactor times as long after each further failure in a
-	// row, up to a minute.
-	firstRetryDelay  = time.Second
-	retryDelayFactor = 2
-	maxRetryDelay    = time.Minute
-)
-
-// Params are what New needs.
-type Params struct {
-	// URL is the endpoint (SWWAF_LOG_REMOTE_URL): SchemeUDP, SchemeTCP or
-	// SchemeTLS, a host and a port.
-	URL *url.URL
-	// RootCAs are the certificates a SchemeTLS endpoint's certificate
-	// must chain to (SWWAF_LOG_REMOTE_TLS_CA_FILE), nil for the host's.
-	RootCAs *x509.CertPool
-	// Buffer is the most lines held while they wait to be sent
-	// (SWWAF_LOG_REMOTE_BUFFER).
-	Buffer int
-	// Facility is the number of the records' syslog facility
-	// (SWWAF_LOG_REMOTE_FACILITY), and AppName their APP-NAME
-	// (SWWAF_LOG_REMOTE_APP_NAME).
-	Facility int
-	AppName  string
-}
-
-// Sender sends lines to the endpoint. Write puts them in its buffer, and
-// Run sends them from there.
-type Sender struct {
-	url       *url.URL
-	tlsConfig *tls.Config
-	// beforeTime and afterTime are the parts of every record's header
-	// before and after its time, as RFC 5424 lays the header out.
-	beforeTime string
-	afterTime  string
-	// records is the buffer: each line's record, framed to be sent.
-	records chan []byte
-	sent    atomic.Int64
-	dropped atomic.Int64
-}
-
-// New returns a Sender for the endpoint params.URL.
-func New(params Params) *Sender {
-	hostname, err := os.Hostname()
-	if err != nil || hostname == "" {
-		hostname = "-" // RFC 5424's value for a field that has none
-	}
-
-	priority := params.Facility*severities + informational
-
-	return &Sender{
-		url: params.URL,
-		tlsConfig: &tls.Config{
-			RootCAs:    params.RootCAs,
-			MinVersion: tls.VersionTLS12,
-		},
-		// The 1 is the version of the format. The process id, the message
-		// id and the structured data have no value.
-		beforeTime: "<" + strconv.Itoa(priority) + ">1 ",
-		afterTime:  " " + hostname + " " + params.AppName + " - - - ",
-		records:    make(chan []byte, params.Buffer),
-	}
-}
-
-// Write puts each line in p in the buffer, as the message of a record of
-// its own, and never waits: when the buffer is full, the oldest record in
-// it is dropped to make room. It is safe for concurrent use.
-func (s *Sender) Write(p []byte) (int, error) {
-	at := requestlog.FormatTime(time.Now())
-
-	for line := range bytes.Lines(p) {
-		line = bytes.TrimSuffix(line, []byte("\n"))
-		if len(line) > 0 {
-			s.put(s.record(at, line))
-		}
-	}
-
-	return len(p), nil
-}
-
-// Sent is how many records have been sent.
-func (s *Sender) Sent() int64 {
-	return s.sent.Load()
-}
-
-// Dropped is how many records were dropped: the oldest in a full buffer,
-// and those whose sending failed.
-func (s *Sender) Dropped() int64 {
-	return s.dropped.Load()
-}
-
-// Depth is how many records are in the buffer.
-func (s *Sender) Depth() int {
-	return len(s.records)
-}
-
-// Run connects to the endpoint and sends each record as it comes into the
-// buffer, until ctx is done. Then it sends the records still in the buffer,
-// on the connection open at that time or, if there is none, on a new one,
-// until none is left or one fails, and returns. How long it may take over
-// that is for the caller to bound.
-//
-// A connection on which a record fails is closed, the record dropped, and
-// a new one made at once. A failed attempt to connect is logged to
-// processLog and followed by the next after firstRetryDelay,
-// retryDelayFactor times as long after each further failure in a row up
-// to maxRetryDelay. Meanwhile the records wait in the buffer.
-func (s *Sender) Run(ctx context.Context, processLog *slog.Logger) {
-	conn := s.send(ctx, processLog)
-	if conn == nil && len(s.records) > 0 {
-		conn, _ = s.dial(context.WithoutCancel(ctx))
-	}
-
-	if conn == nil {
-		return
-	}
-
-	defer func() {
-		_ = conn.Close()
-	}()
-
-	for {
-		select {
-		case record := <-s.records:
-			if s.write(conn, record) != nil {
-				return
-			}
-		default:
-			return
-		}
-	}
-}
-
-// record returns line as an RFC 5424 record made at the time at, framed
-// for the endpoint: on its own over UDP, since each datagram holds one,
-// and over TCP and TLS after its length in bytes and a space, the
-// octet-counted framing of RFC 6587 and RFC 5425.
-func (s *Sender) record(at string, line []byte) []byte {
-	record := make([]byte, 0, len(s.beforeTime)+len(at)+len(s.afterTime)+len(line))
-	record = append(record, s.beforeTime...)
-	record = append(record, at...)
-	record = append(record, s.afterTime...)
-	record = append(record, line...)
-
-	if s.url.Scheme == SchemeUDP {
-		return record
-	}
-
-	return append([]byte(strconv.Itoa(len(record))+" "), record...)
-}
-
-// put adds record to the buffer, first dropping the oldest record in it
-// while it is full.
-func (s *Sender) put(record []byte) {
-	for {
-		select {
-		case s.records <- record:
-			return
-		default:
-		}
-
-		select {
-		case <-s.records:
-			s.dropped.Add(1)
-		default:
-		}
-	}
-}
-
-// send connects to the endpoint and sends each record as it comes into
-// the buffer, until ctx is done, and returns the connection then open, or
-// nil.
-func (s *Sender) send(ctx context.Context, processLog *slog.Logger) net.Conn {
-	delay := firstRetryDelay
-
-	for {
-		conn, err := s.dial(ctx)
-
-		switch {
-		case ctx.Err() != nil:
-			return conn
-		case err != nil:
-			processLog.Warn("connecting to SWWAF_LOG_REMOTE_URL failed",
-				"error", err.Error(), "connecting_again_in", delay.String())
-
-			select {
-			case <-time.After(delay):
-			case <-ctx.Done():
-				return nil
-			}
-
-			delay = min(retryDelayFactor*delay, maxRetryDelay)
-
-			continue
-		}
-
-		delay = firstRetryDelay
-
-		err = s.sendOn(ctx, conn)
-		if err == nil {
-			return conn
-		}
-
-		_ = conn.Close()
-	}
-}
-
-// sendOn sends each record on conn as it comes into the buffer, until one
-// fails, whose error it returns, or ctx is done.
-func (s *Sender) sendOn(ctx context.Context, conn net.Conn) error {
-	for {
-		select {
-		case record := <-s.records:
-			err := s.write(conn, record)
-			if err != nil {
-				return err
-			}
-		case <-ctx.Done():
-			return nil
-		}
-	}
-}
-
-// write sends record on conn, and counts it as sent or, if that fails,
-// as dropped.
-func (s *Sender) write(conn net.Conn, record []byte) error {
-	_, err := conn.Write(record)
-	if err != nil {
-		s.dropped.Add(1)
-
-		return fmt.Errorf("send a record: %w", err)
-	}
-
-	s.sent.Add(1)
-
-	return nil
-}
-
-// dial connects to the endpoint.
-func (s *Sender) dial(ctx context.Context) (net.Conn, error) {
-	dialer := &net.Dialer{Timeout: dialTimeout}
-
-	switch s.url.Scheme {
-	case SchemeUDP:
-		return dialer.DialContext(ctx, "udp", s.url.Host)
-	case SchemeTLS:
-		tlsDialer := &tls.Dialer{NetDialer: dialer, Config: s.tlsConfig}
-
-		return tlsDialer.DialContext(ctx, "tcp", s.url.Host)
-	default:
-		return dialer.DialContext(ctx, "tcp", s.url.Host)
-	}
-}

internal/remotelog/remotelog_test.go

@@ -1,458 +0,0 @@
-package remotelog_test
-
-import (
-	"bufio"
-	"bytes"
-	"context"
-	"crypto/ecdsa"
-	"crypto/elliptic"
-	"crypto/rand"
-	"crypto/tls"
-	"crypto/x509"
-	"crypto/x509/pkix"
-	"encoding/json"
-	"fmt"
-	"io"
-	"log/slog"
-	"math/big"
-	"net"
-	"net/url"
-	"os"
-	"slices"
-	"strconv"
-	"strings"
-	"sync"
-	"testing"
-	"testing/synctest"
-	"time"
-
-	"sneak.berlin/go/smallwebwaf/internal/remotelog"
-)
-
-// The tests run in a synctest bubble, where the time package runs on a
-// clock of the test's own, which starts at 2000-01-01T00:00:00Z: a wait
-// lasts exactly as long as it should, however slowly the test process
-// runs, and synctest.Wait returns once the sender has done all it can
-// before time passes. The endpoint is a listener on the loopback address.
-// A test reads from it only once the records are on their way, and checks
-// the sender's counts first, since a goroutine of the bubble that waits on
-// the network keeps that clock from moving on.
-
-const (
-	// started is the time a record made as a test starts gives.
-	started = "2000-01-01T00:00:00.000Z"
-	appName = "fsn1app1/gitea"
-	// local0 is the number of the default facility, and local0Info the
-	// priority of its records.
-	local0     = 16
-	local0Info = "<134>"
-	// loopback is where the endpoints listen.
-	loopback = "127.0.0.1:0"
-)
-
-func TestRecordsOverUDPGoOnePerDatagram(t *testing.T) {
-	t.Parallel()
-
-	synctest.Test(t, func(t *testing.T) {
-		endpoint, err := (&net.ListenConfig{}).ListenPacket(t.Context(), "udp", loopback)
-		if err != nil {
-			t.Fatalf("listen: %v", err)
-		}
-
-		t.Cleanup(func() { _ = endpoint.Close() })
-
-		sender, _, _ := run(t, params(remotelog.SchemeUDP, endpoint.LocalAddr()))
-
-		_, _ = sender.Write([]byte(`{"type":"request"}` + "\n" + `{"type":"process"}` + "\n"))
-
-		synctest.Wait()
-		wantCounts(t, sender, 2, 0, 0)
-
-		for _, line := range []string{`{"type":"request"}`, `{"type":"process"}`} {
-			datagram := make([]byte, 1024)
-
-			n, _, err := endpoint.ReadFrom(datagram)
-			if err != nil {
-				t.Fatalf("read: %v", err)
-			}
-
-			want := record(t, local0Info, appName, line)
-			if string(datagram[:n]) != want {
-				t.Errorf("datagram %q, want %q", datagram[:n], want)
-			}
-		}
-	})
-}
-
-func TestRecordsOverTCPAreOctetCountedWithTheirFacility(t *testing.T) {
-	t.Parallel()
-
-	synctest.Test(t, func(t *testing.T) {
-		endpoint := listen(t, loopback)
-		endpointParams := params(remotelog.SchemeTCP, endpoint.Addr())
-		endpointParams.Facility = 19 // local3
-		endpointParams.AppName = "gitea"
-		sender, _, _ := run(t, endpointParams)
-
-		_, _ = sender.Write([]byte("first\nsecond\n"))
-
-		synctest.Wait()
-		wantCounts(t, sender, 2, 0, 0)
-
-		frames := bufio.NewReader(accept(t, endpoint))
-		wantFrame(t, frames, record(t, "<158>", "gitea", "first"))
-		wantFrame(t, frames, record(t, "<158>", "gitea", "second"))
-	})
-}
-
-func TestStalledEndpointHoldsUpNoWriteAndOldestRecordsAreDropped(t *testing.T) {
-	t.Parallel()
-
-	synctest.Test(t, func(t *testing.T) {
-		certificate, roots := testCertificate(t)
-		endpoint := listen(t, loopback)
-		endpointParams := params(remotelog.SchemeTLS, endpoint.Addr())
-		endpointParams.RootCAs = roots
-		endpointParams.Buffer = 3
-		sender, _, _ := run(t, endpointParams)
-
-		// The sender connects, and its TLS handshake waits for an answer
-		// the endpoint does not give yet.
-		conn := accept(t, endpoint)
-
-		var stdout bytes.Buffer
-
-		out := io.MultiWriter(&stdout, sender)
-		for i := range 5 {
-			_, _ = fmt.Fprintf(out, "line %d\n", i+1)
-		}
-
-		if stdout.String() != "line 1\nline 2\nline 3\nline 4\nline 5\n" {
-			t.Errorf("stdout has %q", stdout.String())
-		}
-
-		wantCounts(t, sender, 0, 2, 3)
-
-		// Once the endpoint answers, the three newest records are sent.
-		server := tls.Server(conn, &tls.Config{
-			Certificates: []tls.Certificate{certificate},
-			MinVersion:   tls.VersionTLS12,
-		})
-
-		err := server.HandshakeContext(t.Context())
-		if err != nil {
-			t.Fatalf("handshake: %v", err)
-		}
-
-		synctest.Wait()
-		wantCounts(t, sender, 3, 2, 0)
-
-		frames := bufio.NewReader(server)
-		for _, line := range []string{"line 3", "line 4", "line 5"} {
-			wantFrame(t, frames, record(t, local0Info, appName, line))
-		}
-	})
-}
-
-func TestReconnectsWithBackoffAfterTheEndpointGoesAway(t *testing.T) {
-	t.Parallel()
-
-	synctest.Test(t, func(t *testing.T) {
-		endpoint := listen(t, loopback)
-		addr := endpoint.Addr()
-		sender, logged, _ := run(t, params(remotelog.SchemeTCP, addr))
-
-		_, _ = sender.Write([]byte("one\n"))
-
-		synctest.Wait()
-		wantCounts(t, sender, 1, 0, 0)
-
-		conn := accept(t, endpoint)
-		wantFrame(t, bufio.NewReader(conn), record(t, local0Info, appName, "one"))
-
-		// The endpoint goes away. The sender notices when a record fails,
-		// and tries to connect again at once, then a second later, then two
-		// seconds after that.
-		_ = conn.Close()
-		_ = endpoint.Close()
-
-		writeUntilDropped(t, sender, 1)
-		sent := sender.Sent()
-
-		_, _ = sender.Write([]byte("two\n"))
-
-		time.Sleep(time.Second)
-		synctest.Wait()
-
-		endpoint = listen(t, addr.String())
-
-		time.Sleep(2*time.Second - time.Nanosecond)
-		synctest.Wait()
-		wantCounts(t, sender, sent, 1, 1)
-
-		// The endpoint is back, and the record waiting is sent.
-		time.Sleep(time.Nanosecond)
-		synctest.Wait()
-		wantCounts(t, sender, sent+1, 1, 0)
-
-		conn = accept(t, endpoint)
-		wantFrame(t, bufio.NewReader(conn), record(t, local0Info, appName, "two"))
-		wantRetries(t, logged, "1s", "2s")
-
-		// Having connected, the sender waits a second again after the
-		// next failure.
-		_ = conn.Close()
-		_ = endpoint.Close()
-
-		writeUntilDropped(t, sender, 2)
-		wantRetries(t, logged, "1s", "2s", "1s")
-	})
-}
-
-func TestRecordsWaitingAtTheStopAreSent(t *testing.T) {
-	t.Parallel()
-
-	synctest.Test(t, func(t *testing.T) {
-		// Nothing listens at addr when the sender starts: it fails to
-		// connect, and waits a second to try again.
-		endpoint := listen(t, loopback)
-		addr := endpoint.Addr()
-		_ = endpoint.Close()
-
-		sender, logged, stop := run(t, params(remotelog.SchemeTCP, addr))
-
-		synctest.Wait()
-		wantRetries(t, logged, "1s")
-
-		_, _ = sender.Write([]byte("one\ntwo\n"))
-		endpoint = listen(t, addr.String())
-
-		// Stopped before that second is over, it connects to send them.
-		stop()
-		wantCounts(t, sender, 2, 0, 0)
-
-		frames := bufio.NewReader(accept(t, endpoint))
-		wantFrame(t, frames, record(t, local0Info, appName, "one"))
-		wantFrame(t, frames, record(t, local0Info, appName, "two"))
-	})
-}
-
-// output collects what the sender logs.
-type output struct {
-	mu  sync.Mutex
-	buf bytes.Buffer
-}
-
-// Write adds lines the sender logs.
-func (o *output) Write(p []byte) (int, error) {
-	o.mu.Lock()
-	defer o.mu.Unlock()
-
-	return o.buf.Write(p)
-}
-
-// text returns everything logged so far.
-func (o *output) text() string {
-	o.mu.Lock()
-	defer o.mu.Unlock()
-
-	return o.buf.String()
-}
-
-// params returns the settings of a Sender for the endpoint at addr, in
-// the form scheme names: room for ten lines, the default facility, and
-// appName.
-func params(scheme string, addr net.Addr) remotelog.Params {
-	return remotelog.Params{
-		URL:      &url.URL{Scheme: scheme, Host: addr.String()},
-		Buffer:   10,
-		Facility: local0,
-		AppName:  appName,
-	}
-}
-
-// run runs a Sender with settings until the test ends or the function
-// it returns is called, which waits for Run to return. It returns the
-// Sender, and what it logs.
-func run(t *testing.T, settings remotelog.Params) (*remotelog.Sender, *output, func()) {
-	t.Helper()
-
-	sender := remotelog.New(settings)
-	logged := &output{}
-	ctx, cancel := context.WithCancel(t.Context())
-	ran := make(chan struct{})
-
-	go func() {
-		sender.Run(ctx, slog.New(slog.NewJSONHandler(logged, nil)))
-		close(ran)
-	}()
-
-	stop := func() {
-		cancel()
-		<-ran
-	}
-	t.Cleanup(stop)
-
-	return sender, logged, stop
-}
-
-// listen returns a TCP listener at addr, closed when the test ends.
-func listen(t *testing.T, addr string) net.Listener {
-	t.Helper()
-
-	listener, err := (&net.ListenConfig{}).Listen(t.Context(), "tcp", addr)
-	if err != nil {
-		t.Fatalf("listen: %v", err)
-	}
-
-	t.Cleanup(func() { _ = listener.Close() })
-
-	return listener
-}
-
-// accept returns the next connection to listener, closed when the test
-// ends.
-func accept(t *testing.T, listener net.Listener) net.Conn {
-	t.Helper()
-
-	conn, err := listener.Accept()
-	if err != nil {
-		t.Fatalf("accept: %v", err)
-	}
-
-	t.Cleanup(func() { _ = conn.Close() })
-
-	return conn
-}
-
-// record returns the record of line made as the test started, with the
-// priority and the app name given.
-func record(t *testing.T, priority, app, line string) string {
-	t.Helper()
-
-	hostname, err := os.Hostname()
-	if err != nil || hostname == "" {
-		hostname = "-"
-	}
-
-	return priority + "1 " + started + " " + hostname + " " + app + " - - - " + line
-}
-
-// wantFrame reads the next octet-counted frame from frames, and checks
-// that it holds want.
-func wantFrame(t *testing.T, frames *bufio.Reader, want string) {
-	t.Helper()
-
-	count, err := frames.ReadString(' ')
-	if err != nil {
-		t.Fatalf("read a frame's length: %v", err)
-	}
-
-	length, err := strconv.Atoi(strings.TrimSuffix(count, " "))
-	if err != nil {
-		t.Fatalf("frame starts %q, not with its length", count)
-	}
-
-	got := make([]byte, length)
-
-	_, err = io.ReadFull(frames, got)
-	if err != nil {
-		t.Fatalf("read a frame: %v", err)
-	}
-
-	if string(got) != want {
-		t.Errorf("frame %q, want %q", got, want)
-	}
-}
-
-// wantCounts checks the records sender has sent, dropped and holds in
-// its buffer.
-func wantCounts(
-	t *testing.T, sender *remotelog.Sender, sent, dropped int64, depth int,
-) {
-	t.Helper()
-
-	if sender.Sent() != sent || sender.Dropped() != dropped || sender.Depth() != depth {
-		t.Fatalf("sent %d, dropped %d, %d in the buffer; want %d, %d and %d",
-			sender.Sent(), sender.Dropped(), sender.Depth(), sent, dropped, depth)
-	}
-}
-
-// writeUntilDropped writes a line at a time until the count of records
-// sender has dropped reaches dropped. The records it sends on a
-// connection the endpoint has closed are lost before one fails; how many
-// depends on when the endpoint's host answers that the connection is
-// gone.
-func writeUntilDropped(t *testing.T, sender *remotelog.Sender, dropped int64) {
-	t.Helper()
-
-	for sender.Dropped() < dropped {
-		_, _ = sender.Write([]byte("lost\n"))
-
-		synctest.Wait()
-	}
-}
-
-// wantRetries checks that the sender logged a failed attempt to connect
-// for each of delays, the time until the next attempt, in order, and
-// logged nothing else.
-func wantRetries(t *testing.T, logged *output, delays ...string) {
-	t.Helper()
-
-	var got []string
-
-	for line := range strings.Lines(logged.text()) {
-		var fields map[string]any
-
-		err := json.Unmarshal([]byte(line), &fields)
-		if err != nil || fields["msg"] != "connecting to SWWAF_LOG_REMOTE_URL failed" {
-			t.Fatalf("logged %q", line)
-		}
-
-		delay, _ := fields["connecting_again_in"].(string)
-		got = append(got, delay)
-	}
-
-	if !slices.Equal(got, delays) {
-		t.Errorf("logged failures to connect again in %v, want %v", got, delays)
-	}
-}
-
-// testCertificate returns a certificate for 127.0.0.1 that is its own
-// CA, and a pool that holds it.
-func testCertificate(t *testing.T) (tls.Certificate, *x509.CertPool) {
-	t.Helper()
-
-	key, err := ecdsa.GenerateKey(elliptic.P256(), rand.Reader)
-	if err != nil {
-		t.Fatalf("generate a key: %v", err)
-	}
-
-	template := &x509.Certificate{
-		SerialNumber:          big.NewInt(1),
-		Subject:               pkix.Name{CommonName: "smallwebwaf test CA"},
-		NotBefore:             time.Now().Add(-time.Hour),
-		NotAfter:              time.Now().Add(time.Hour),
-		IsCA:                  true,
-		BasicConstraintsValid: true,
-		KeyUsage:              x509.KeyUsageCertSign | x509.KeyUsageDigitalSignature,
-		ExtKeyUsage:           []x509.ExtKeyUsage{x509.ExtKeyUsageServerAuth},
-		IPAddresses:           []net.IP{net.IPv4(127, 0, 0, 1)},
-	}
-
-	der, err := x509.CreateCertificate(rand.Reader, template, template,
-		&key.PublicKey, key)
-	if err != nil {
-		t.Fatalf("create a certificate: %v", err)
-	}
-
-	certificate, err := x509.ParseCertificate(der)
-	if err != nil {
-		t.Fatalf("parse the certificate: %v", err)
-	}
-
-	roots := x509.NewCertPool()
-	roots.AddCert(certificate)
-
-	return tls.Certificate{Certificate: [][]byte{der}, PrivateKey: key}, roots
-}

internal/requestlog/requestlog.go

@@ -9,6 +9,8 @@ import (
 	"io"
 	"log/slog"
 	"time"
+
+	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
 )
 
 // The action a request line names: what smallwebwaf did with the
@@ -45,32 +47,71 @@ const OffenceLimit = "limit"
 // timeLayout is RFC 3339 with milliseconds.
 const timeLayout = "2006-01-02T15:04:05.000Z07:00"
 
-// Line is one request's line in the request log. The field names are
-// those of the "Request log" section of SPEC.md.
+// Line is one request's line in the request log. The field names, and
+// their order, are those of the "Request log" section of SPEC.md. A field
+// that may not apply to a request is left out of its line when it does
+// not.
 //
 //nolint:tagliatelle // SPEC.md's request log names its fields in snake_case
 type Line struct {
 	Type string `json:"type"`
+
+	// The standard web log fields. Scheme is how the client reached
+	// smallwebwaf, or the trusted proxy in front of it.
 	Time          string `json:"time"`
+	Instance      string `json:"instance"`
 	ClientIP      string `json:"client_ip"`
-	PeerIP         string `json:"peer_ip"`
-	Country        string `json:"country"`
 	Method        string `json:"method"`
+	Scheme        string `json:"scheme"`
 	Host          string `json:"host"`
 	Path          string `json:"path"`
 	Query         string `json:"query"`
 	Protocol      string `json:"protocol"`
 	Status        int    `json:"status"`
-	UpstreamStatus int    `json:"upstream_status,omitempty"`
 	RequestBytes  int64  `json:"request_bytes"`
 	ResponseBytes int64  `json:"response_bytes"`
 	Referer       string `json:"referer"`
 	UserAgent     string `json:"user_agent"`
+
+	// Request detail. RequestID is the X-Request-ID a trusted proxy sent,
+	// or a new one, and is sent on to the app. ForwardedFor is the
+	// X-Forwarded-For header as received. ClientGroup is the netblock the
+	// client is counted as.
+	RequestID    string `json:"request_id"`
+	PeerIP       string `json:"peer_ip"`
+	ForwardedFor string `json:"forwarded_for,omitempty"`
+	ClientGroup  string `json:"client_group"`
+	Country      string `json:"country"`
+	ContentType  string `json:"content_type,omitempty"`
+	// ContentLength is the length of its body the request announced.
+	ContentLength int64 `json:"content_length,omitempty"`
+	// RequestHeaders are the headers SWWAF_LOG_REQUEST_HEADERS names that
+	// the request carried, by name in lower case.
+	RequestHeaders   map[string]string `json:"request_headers,omitempty"`
+	HasAuthorization bool              `json:"has_authorization,omitempty"`
+	HasCookie        bool              `json:"has_cookie,omitempty"`
+	// Websocket is true when the connection was upgraded, as for a
+	// WebSocket.
+	Websocket bool `json:"websocket,omitempty"`
+
+	// Response detail, from the headers of the answer: the app's, as
+	// passed on, or those of smallwebwaf's own. Aborted is true when the
+	// client went away early.
+	ResponseContentType string `json:"response_content_type,omitempty"`
+	UpstreamStatus      int    `json:"upstream_status,omitempty"`
+	CacheControl        string `json:"cache_control,omitempty"`
+	Location            string `json:"location,omitempty"`
+	Aborted             bool   `json:"aborted,omitempty"`
+
+	// The decision.
 	Action string `json:"action"`
 	// WouldAction is, in observe mode, the action enforce mode would have
 	// taken with a request it would have refused: ActionDenied,
 	// ActionBanned, ActionCountryDenied or ActionRateLimited.
 	WouldAction string `json:"would_action,omitempty"`
+	// Counts are the client's requests as the rate limits counted them
+	// with this one, for a request they counted.
+	Counts ratelimit.Counts `json:"counts,omitzero"`
 	// LimitHit is the window whose rate limit the request went over:
 	// minute, hour or day.
 	LimitHit string `json:"limit_hit,omitempty"`
@@ -79,11 +120,18 @@ type Line struct {
 	// BanExpires is when the ban the request made, or was refused under,
 	// ends: a time, or "permanent".
 	BanExpires string `json:"ban_expires,omitempty"`
-	// Aborted is true when the client went away early.
-	Aborted bool `json:"aborted,omitempty"`
-	// DurationTotal and DurationUpstreamTotal are in milliseconds.
+
+	// The timings, in milliseconds. DurationChecks is the time until the
+	// checks were done. DurationUpstreamConnect, DurationUpstreamFirstByte
+	// and DurationUpstreamTotal run from when the request was handed to the
+	// app: until there was a connection to it, until the first byte of its
+	// answer arrived, and until the end. Each but DurationTotal is nil for
+	// a request that did not get that far.
 	DurationTotal             float64  `json:"duration_total"`
-	DurationUpstreamTotal float64 `json:"duration_upstream_total,omitempty"`
+	DurationChecks            *float64 `json:"duration_checks,omitempty"`
+	DurationUpstreamConnect   *float64 `json:"duration_upstream_connect,omitempty"`
+	DurationUpstreamFirstByte *float64 `json:"duration_upstream_first_byte,omitempty"`
+	DurationUpstreamTotal     *float64 `json:"duration_upstream_total,omitempty"`
 }
 
 // Write writes line to w as one JSON line marked "type":"request".

internal/requestlog/requestlog_test.go

@@ -50,7 +50,11 @@ func TestWriteWritesOneJSONLineMarkedRequest(t *testing.T) {
 	}
 
 	unset := []string{
-		"upstream_status", "limit_hit", "offence", "ban_expires", "aborted",
+		"forwarded_for", "content_type", "content_length", "request_headers",
+		"has_authorization", "has_cookie", "websocket", "response_content_type",
+		"upstream_status", "cache_control", "location", "aborted", "counts",
+		"limit_hit", "offence", "ban_expires", "duration_checks",
+		"duration_upstream_connect", "duration_upstream_first_byte",
 		"duration_upstream_total",
 	}
 	for _, name := range unset {

internal/smallwebwaf/smallwebwaf.go

@@ -18,7 +18,6 @@ import (
 	"sneak.berlin/go/smallwebwaf/internal/config"
 	"sneak.berlin/go/smallwebwaf/internal/lookup"
 	"sneak.berlin/go/smallwebwaf/internal/proxy"
-	"sneak.berlin/go/smallwebwaf/internal/remotelog"
 	"sneak.berlin/go/smallwebwaf/internal/requestlog"
 	"sneak.berlin/go/smallwebwaf/internal/state"
 )
@@ -28,11 +27,6 @@ import (
 // runit and docker wait a little longer before they kill the process.
 const shutdownTimeout = 5 * time.Second
 
-// remoteLogStopTimeout is how long, as smallwebwaf stops, the log lines
-// still waiting are sent to SWWAF_LOG_REMOTE_URL before they are given
-// up. stdout has carried them.
-const remoteLogStopTimeout = 2 * time.Second
-
 // Params are what Run needs from the process.
 type Params struct {
 	// Version is the version of the binary, set when it is built.
@@ -75,40 +69,16 @@ func Run(ctx context.Context, params Params) int {
 		return 1
 	}
 
-	// While SWWAF_LOG_REMOTE_URL is set, every line on stdout from here on
-	// is sent there too.
-	stdout := params.Stdout
-
-	var remote *remotelog.Sender
-
-	if cfg.LogRemoteURL != nil {
-		remote = remotelog.New(remotelog.Params{
-			URL:      cfg.LogRemoteURL,
-			RootCAs:  cfg.LogRemoteTLSCAs,
-			Buffer:   cfg.LogRemoteBuffer,
-			Facility: cfg.LogRemoteFacility,
-			AppName:  cfg.LogRemoteAppName,
-		})
-		stdout = io.MultiWriter(params.Stdout, remote)
-		processLog = requestlog.NewProcessLogger(stdout)
-
-		stopSending := startSending(ctx, remote, processLog)
-		defer stopSending()
-	}
-
 	// The state files give times in UTC.
 	now := func() time.Time { return time.Now().UTC() }
 
 	server := proxy.New(proxy.Params{
 		Config:     cfg,
-		RequestLog: stdout,
+		RequestLog: params.Stdout,
 		ProcessLog: processLog,
 		GeoJSURL:   lookup.URL,
 		Now:        now,
 	})
-	if remote != nil {
-		server.Metrics.AddRemoteLog(remote)
-	}
 
 	files, err := state.Load(state.Params{
 		Dir:             cfg.StateDir,
@@ -143,31 +113,6 @@ func Run(ctx context.Context, params Params) int {
 	return serve(ctx, server.Server, listener, files, processLog)
 }
 
-// startSending runs remote until the function it returns is called, which
-// then waits at most remoteLogStopTimeout for the lines still waiting to
-// be sent. Sending goes on after ctx is done, so that the lines written
-// while smallwebwaf stops are sent too.
-func startSending(
-	ctx context.Context, remote *remotelog.Sender, processLog *slog.Logger,
-) func() {
-	sending, stop := context.WithCancel(context.WithoutCancel(ctx))
-	sent := make(chan struct{})
-
-	go func() {
-		remote.Run(sending, processLog)
-		close(sent)
-	}()
-
-	return func() {
-		stop()
-
-		select {
-		case <-sent:
-		case <-time.After(remoteLogStopTimeout):
-		}
-	}
-}
-
 // serve serves requests on listener, writes the state files as they are
 // due, and takes in an admin's edits of them, until ctx is done. Then it
 // gives the requests in progress shutdownTimeout to finish, and writes

internal/smallwebwaf/smallwebwaf_test.go

@@ -10,8 +10,6 @@ import (
 	"net/http/httptest"
 	"os"
 	"path/filepath"
-	"slices"
-	"strconv"
 	"strings"
 	"sync"
 	"testing"
@@ -318,110 +316,6 @@ func TestBanAddedAndLiftedByEditingBansJSON(t *testing.T) {
 	})
 }
 
-func TestEveryLineIsAlsoSentToTheRemoteLogEndpoint(t *testing.T) {
-	t.Parallel()
-
-	endpoint, err := (&net.ListenConfig{}).Listen(t.Context(), "tcp", localhost+":0")
-	if err != nil {
-		t.Fatalf("listen: %v", err)
-	}
-
-	defer func() {
-		_ = endpoint.Close()
-	}()
-
-	env := map[string]string{
-		listenAddr:             localhost + ":0",
-		upstreamURL:            startApp(t),
-		stateDir:               t.TempDir(),
-		"SWWAF_LOG_REMOTE_URL": "syslog+tcp://" + endpoint.Addr().String(),
-	}
-
-	out := runUntilStopped(t, env, func(url string) {
-		wantGreeting(t, url)
-	})
-	out.line(t, "type", "request")
-
-	// smallwebwaf connected as it started, and closes the connection once
-	// it has sent the lines written as it stopped.
-	conn, err := endpoint.Accept()
-	if err != nil {
-		t.Fatalf("accept: %v", err)
-	}
-
-	received, err := io.ReadAll(conn)
-	_ = conn.Close()
-
-	if err != nil {
-		t.Fatalf("read: %v", err)
-	}
-
-	// Lines written at once by several goroutines may reach stdout and
-	// the endpoint in different orders.
-	sent := messages(t, string(received))
-	written := slices.Collect(strings.Lines(out.text()))
-
-	slices.Sort(sent)
-	slices.Sort(written)
-
-	if !slices.Equal(sent, written) {
-		t.Errorf("sent\n%v\nwrote\n%v", sent, written)
-	}
-}
-
-func TestStalledRemoteLogEndpointHoldsUpNoRequest(t *testing.T) {
-	t.Parallel()
-
-	const token = "0123456789abcdef0123456789abcdef"
-
-	// The endpoint takes connections and never answers, so the TLS
-	// handshake of each waits on it, and no line is ever sent.
-	endpoint, err := (&net.ListenConfig{}).Listen(t.Context(), "tcp", localhost+":0")
-	if err != nil {
-		t.Fatalf("listen: %v", err)
-	}
-
-	defer func() {
-		_ = endpoint.Close()
-	}()
-
-	env := map[string]string{
-		listenAddr:                localhost + ":0",
-		upstreamURL:               startApp(t),
-		stateDir:                  t.TempDir(),
-		"SWWAF_LOG_REMOTE_URL":    "syslog+tls://" + endpoint.Addr().String(),
-		"SWWAF_LOG_REMOTE_BUFFER": "1",
-		"SWWAF_METRICS_TOKEN":     token,
-	}
-
-	out := runUntilStopped(t, env, func(url string) {
-		wantGreeting(t, url)
-
-		// More than one line has been written, and the buffer holds the
-		// last.
-		metrics := metricsText(t, url+"_smallwebwaf/metrics", token)
-		for _, series := range []string{
-			"smallwebwaf_remote_log_lines_sent_total 0",
-			"smallwebwaf_remote_log_buffer_depth 1",
-		} {
-			if !strings.Contains(metrics, "\n"+series+"\n") {
-				t.Errorf("no %q in the metrics:\n%s", series, metrics)
-			}
-		}
-
-		if strings.Contains(metrics, "\nsmallwebwaf_remote_log_lines_dropped_total 0\n") ||
-			!strings.Contains(metrics, "\nsmallwebwaf_remote_log_lines_dropped_total ") {
-			t.Errorf("no line dropped in the metrics:\n%s", metrics)
-		}
-
-		// Closed, the endpoint refuses the connection made to send the
-		// lines still waiting at the stop, which then does not wait.
-		_ = endpoint.Close()
-	})
-
-	out.line(t, "type", "request")
-}
-
 func TestStateFileThatDoesNotParseStopsTheStart(t *testing.T) {
 	t.Parallel()
 
@@ -542,6 +436,7 @@ func wantStartingLine(t *testing.T, line map[string]any, appURL, dir string) {
 		"SWWAF_RATE_LIMIT_PER_MINUTE":           "1000",
 		"SWWAF_RATE_LIMIT_PER_HOUR":             "10000",
 		rateLimitPerDay:                         "50000",
+		"SWWAF_RATE_LIMIT_EXEMPT_PATHS":         "",
 		"SWWAF_DENIED_COUNTRIES":                "",
 		"SWWAF_EXCLUSIVELY_ALLOWED_COUNTRIES":   "",
 		"SWWAF_BAN_RESPONSE":                    "403",
@@ -589,69 +484,6 @@ func wantGreeting(t *testing.T, url string) {
 	}
 }
 
-// messages returns the message of each record in received, octet-counted
-// frames of RFC 5424 records with the default facility and app name, each
-// with the newline that ends a line on stdout.
-func messages(t *testing.T, received string) []string {
-	t.Helper()
-
-	hostname, _ := os.Hostname()
-	header := " " + hostname + " " + hostname + " - - - "
-
-	var found []string
-
-	for received != "" {
-		count, rest, _ := strings.Cut(received, " ")
-
-		length, err := strconv.Atoi(count)
-		if err != nil || length > len(rest) {
-			t.Fatalf("no frame at %q", received)
-		}
-
-		record := rest[:length]
-		received = rest[length:]
-
-		_, message, ok := strings.Cut(record, header)
-		if !ok || !strings.HasPrefix(record, "<134>1 ") {
-			t.Fatalf("record %q, want priority <134> and header %q", record, header)
-		}
-
-		found = append(found, message+"\n")
-	}
-
-	return found
-}
-
-// metricsText asks for the metrics at url with token, and returns them.
-func metricsText(t *testing.T, url, token string) string {
-	t.Helper()
-
-	req, err := http.NewRequestWithContext(t.Context(), http.MethodGet, url,
-		http.NoBody)
-	if err != nil {
-		t.Fatalf("new request: %v", err)
-	}
-
-	req.Header.Set("Authorization", "Bearer "+token)
-
-	transport := &http.Transport{}
-	defer transport.CloseIdleConnections()
-
-	res, err := (&http.Client{Transport: transport}).Do(req)
-	if err != nil {
-		t.Fatalf("request: %v", err)
-	}
-
-	body, err := io.ReadAll(res.Body)
-	_ = res.Body.Close()
-
-	if err != nil || res.StatusCode != http.StatusOK {
-		t.Fatalf("metrics answered %d (%v)", res.StatusCode, err)
-	}
-
-	return string(body)
-}
-
 // wantRefused checks that a request to url is refused with 403, the
 // default SWWAF_BAN_RESPONSE.
 func wantRefused(t *testing.T, url string) {