Files
smallwebwaf/docs/request-log.md
T
sneak a8b978dfc9
check / check (push) Successful in 4m12s
Name request log actions so they say what they mean (closes #229)
Rename too_large, rate_limited, rule_blocked and denied, and split banned
into temporarily_banned and permanently_banned by whether the ban runs out.
A client under both a temporary and a permanent ban gets the permanent one.
A request that makes a ban permanent gets permanently_banned. A ban rule, a
trap path or a CrowdSec decision gets the value for the ban it makes, and in
observe mode would_action names the ban enforce mode would have made.

The offence kind rule_blocked follows, as a metric label and a key in
clients.json.

Model: opus-5-5
2026-11-09 04:34:40 +00:00

244 lines
12 KiB
Markdown

# The request log's fields
The fields of the JSON objects `rproxy` and `discriminator` write about each
request. "Request log" and "The log" in [`SPEC.md`](../SPEC.md) say when a line
is written and how the log is sent to a syslog server. A field that does not
apply to a request is left out.
## `discriminator`'s lines
`sww discriminator` writes two lines for each question it answers, joined by
`request_id`. The field `discriminator_line` says which of the two a line is:
- `decision`: the line it writes once it has answered the question;
- `report`: the line it writes when `rproxy`'s report comes, with everything
known. The repetition is intended.
A request to its own endpoints writes one line, without `discriminator_line`. A
report writes no line but the `report` line of the request it names.
These questions write no line:
- a question refused with `400` (see "The question" under "`discriminator`" in
[`SPEC.md`](../SPEC.md));
- a question whose body stopped arriving, which gets no answer.
A `report` line:
```
{"type":"request","discriminator_line":"report","time":"2026-10-03T12:00:00.123Z","instance":"fsn1/discriminator","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","asn":"AS64496","as_name":"Example Net","country":"DE","request_headers":{"accept":"*/*"},"action":"forward","counts":{"minute":1,"hour":12,"day":40,"minute_bytes":5120,"hour_bytes":61440,"day_bytes":204800},"waf_score":0,"duration_total":3.217,"duration_checks":0.041,"duration_waf":0.029,"duration_upstream_total":3.104}
```
### Every line
Every one of these lines has:
- `type`: `request` (the process's own messages have `process`);
- the standard web log fields;
- `request_id`, `peer_ip` and `client_group`;
- `asn`, `as_name` and `country`;
- `action` and `duration_total`.
### Standard web log fields
- `time`: when `discriminator` had read the question's body, RFC 3339 with
milliseconds, in UTC. The `report` line gives the same time as the `decision`
line.
- `instance`: `SWW_INSTANCE_NAME`.
- `client_ip`: the visitor's address, as `rproxy` worked it out.
- `method`, `path` and `query`: the visitor's request.
- `scheme`: how the visitor reached `rproxy` or the trusted proxy in front of
it.
- `host`: the site the visitor asked for.
- `protocol`: the question's own, `HTTP/1.1`.
- `status`:
- on the `decision` line, what `discriminator` answered: `200` for `allow`,
the status of `deny`, or `0` for `close`, as the visitor is then sent
nothing;
- on the `report` line, what the visitor got, `0` if nothing.
- `request_bytes`:
- on the `decision` line, how much of the question's body the Core Rule Set
read;
- on the `report` line, the bytes of the visitor's body that `rproxy` read,
with what a WebSocket carried from the visitor.
- `response_bytes`:
- on the `decision` line, the body of `discriminator`'s answer;
- on the `report` line, the bytes of the answer's body, with what a
WebSocket carried from the app.
- `referer` and `user_agent`.
### Request detail
- `request_id`: the id `rproxy` made for the request when it arrived.
- `peer_ip`: the address of `rproxy`'s TCP peer, normally traefik.
- `forwarded_for`: the `X-Forwarded-For` header the visitor's request came with.
- `client_group`: the client as rate limiting counts it, an IPv4 address as a
/32 or an IPv6 group.
- `asn`, `as_name` and `country`: the client's, as looked up. Each is empty
when:
- lookups are off;
- the client is not looked up;
- the source cannot place the client;
- GeoJS had not answered by the time `discriminator` answered.
- `content_type`: the visitor's `Content-Type`.
- `content_length`: the body length the visitor announced.
- `request_headers`: the headers listed in `SWW_LOG_REQUEST_HEADERS`, by name in
lower case.
- `has_authorization` and `has_cookie`: true when the request had those headers.
Their values are never logged.
### Response detail
- `response_content_type`: the type of `discriminator`'s own answer.
- `aborted`: true when `rproxy` went away before the answer.
### Decision
- `action`: what was done:
- `forward`: answered `allow`, so that `rproxy` passes it to the app;
- `client_denied`: refused for `SWW_DENY_NETS`, for a reputation source with
the action `deny`, or for a tag in `SWW_TAG_DENY`;
- `temporarily_banned`: refused under a ban that runs out, or for a `ban`
rule, a trap path or a CrowdSec decision that made such a ban;
- `permanently_banned`: refused under a ban that never runs out, including a
ban this request made or made permanent;
- `country_denied`, `client_is_rate_limited`, `blocked_by_block_rule` and
`waf_blocked`: refused by that check;
- `request_header_too_large`: over a header limit;
- `admin`: answered at one of `discriminator`'s own endpoints, or `404` for
a path under `/_sww/`.
- `would_action`: in `observe` mode, what `enforce` mode would have done with a
request it would have refused. `action` then names what was done, normally
`forward`.
- `heuristic`: the heuristic that refused the request, in `observe` mode too. It
is left out when none did.
- `heuristic_figures`: an object of the figures that heuristic acted on. Each
heuristic and its figures:
- `deny_nets`: `netblock`, the entry of `SWW_DENY_NETS` the client is in;
- `active_ban`: `netblock`, the ban's netblock, and `ban_expires`;
- `countries`: `country`, and `setting`, the country list that refused it;
- `tag_deny`: `tag`, the tag of `SWW_TAG_DENY` the request carries;
- `blocklists`: `lists`, the blocklist URLs that list the client;
- `crowdsec`: `scenario`, the decision's scenario, and `expires`, when the
decision ends;
- `dnsbl`: `zones`, the DNS blocklist zones that list the client, their keys
masked;
- `abuseipdb`: `score`, and `min_score`, `SWW_ABUSEIPDB_MIN_SCORE`;
- `rate_limits`: `window`, `count` and `limit`;
- `trap_paths`: `path`, the trap path asked for;
- `rule_files`: `rule_id` and `rule_action`, of the rule that refused it;
- `header_limits`: `fields`, `fields_limit`, `cookies` and `cookies_limit`;
- `core_rule_set`: `score`, and `threshold`, `SWW_WAF_ANOMALY_THRESHOLD`;
- `refusal_limit`: `window`, `count` and `limit`, of the error burst;
- `byte_limits`: `window`, `count` and `limit`, the count in bytes.
- `after_answer_heuristic`: the heuristic that banned the client after
`discriminator` answered the request, in `observe` mode too: `refusal_limit`
or `byte_limits`.
- `after_answer_heuristic_figures`: an object of the figures that heuristic
acted on, as listed above.
`byte_limits` bans when the report comes, so only the `report` line names
it.
- `limit_percent` and `limit_percent_setting`: the client's percentage of the
rate limits and the setting that lowered it, when one did. `bytes_percent` and
`bytes_percent_setting` do the same for the byte limits.
- `counts`: the client's totals as rate limiting counts them, this request
included. It is left out when rate limiting did not count the request. It
holds:
- `minute`, `hour` and `day`: requests;
- `minute_bytes`, `hour_bytes` and `day_bytes`: the body bytes
`SWW_BYTES_COUNT` names, in that window.
A count can have a fraction (see "Counting method" in
[`SPEC.md`](../SPEC.md)). The bytes counted for an allowed request and its
response are added when its report comes. So on the `decision` line, the
three byte totals leave them out.
- `limit_hit`: the limit broken:
- `minute`, `hour` or `day` for a rate limit;
- `minute_bytes`, `hour_bytes` or `day_bytes` for a byte limit;
- `error_burst`.
When the bytes counted for a request and its response break a limit, the
request has been passed on whole, so its `action` stays `forward`. Only its
`report` line gives that limit.
- `rule_ids`: the rule file rules that matched, in order, up to the one that
refused.
- `waf_score` and `waf_rule_ids`: the Core Rule Set's score and the rules that
matched, for a request it inspected.
- `reputation`: the sources the client is on, in this order:
- blocklist URLs;
- the CrowdSec decision list's URL;
- DNS blocklist zones;
- `abuseipdb`.
- `tags`: the request's tags, sorted, left out when it has none. Each tag and
where it comes from is under "Request tags" in [`SPEC.md`](../SPEC.md).
- `offence`: `limit`, for a request that broke a limit.
- `ban_expires`: when the client's ban ends, for a request that made one or was
refused under one: a time, or `permanent`.
### Timings
All in milliseconds:
- `duration_total`:
- on the `decision` line, from `discriminator` having read the question's
body to the line;
- on the `report` line, from `rproxy` having read the request's headers to
the end of the answer.
- `duration_checks`: to the end of the checks;
- `duration_waf`: the part of that the Core Rule Set took;
- `duration_upstream_total`: on the `report` line of an allowed request, from
the hand-over to the app to the end of the answer.
### Requests to its own endpoints
The line of a request to `discriminator`'s own endpoints has these fields, with
these meanings where they differ:
- `client_ip` and `peer_ip`: the request's TCP peer.
- `request_id`: a new random one of 26 letters and digits.
- `scheme`: `http`.
- `time`: when the request's headers had been read.
- `request_bytes`: the bytes read of a ban to add, and otherwise `0`.
- `action`: `admin`.
- `duration_total`: from the request's headers being read to the line.
## `rproxy`'s line
`sww rproxy` writes one short line for each request. `request_id` joins it to
`discriminator`'s two. It has these fields and no others:
- `type`: `request`.
- `time`: when the request arrived, RFC 3339 with milliseconds, in UTC.
- `request_id`: the id `rproxy` made for the request when it arrived.
- `client_ip`: the visitor's address.
- `host` and `method`.
- `path` and `query`: as the visitor sent them.
- `status`: what the visitor got, `0` if nothing.
- `request_bytes`: the bytes of the visitor's body that `rproxy` read, with what
a WebSocket carried from the visitor.
- `response_bytes`: the bytes of the answer's body, with what a WebSocket
carried from the app.
- `duration_request`: milliseconds from the request's headers being read until
the app had been sent the whole request, or the answer started if that was
sooner. It includes the wait for `discriminator`.
- `duration_response`: milliseconds from then until the end of the answer.
- `disposition`: what was done with the request: `allow`, `deny` or `close`. It
is `discriminator`'s answer, or the value of `SWRP_DEFAULT_DISPOSITION`. It is
left out when:
- `discriminator` was not asked, as for the health check;
- the visitor went away while `discriminator` was being asked;
- `discriminator`'s answer had no valid `X-Sww-Disposition`;
- `rproxy` could not pass on `discriminator`'s answer, and answered `502`.
- `default_disposition`: `true` when `SWRP_DEFAULT_DISPOSITION` gave
`disposition`, and otherwise left out.
For example:
```
{"type":"request","time":"2026-10-03T12:00:00.123Z","request_id":"7Q2NHZ4KJ3VXW5YB6R3MEFTD2A","client_ip":"203.0.113.9","host":"app.example","method":"GET","path":"/","query":"","status":200,"request_bytes":0,"response_bytes":5120,"duration_request":1.204,"duration_response":3.104,"disposition":"allow"}
```