From a6634454cdec14070c50d8a1b460698ec39cbfdd Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Thu, 8 Oct 2026 02:14:12 +0200 Subject: [PATCH] Read SWWAF_IPV6_GROUP_PREFIX, SWWAF_MAX_TRACKED_CLIENTS and SWWAF_LOG_LEVEL (closes #112) The IPv6 group that is one client, the size of the table of clients and the level of the process's own lines become settings. clientGroup reads the group length from them, so limits, bans, history, lookups, AbuseIPDB scores and per-client anomaly counters all follow it; ratelimit.New takes the table size; the process logger takes the level once the settings are read, and request lines, written apart from it, are never held back. Judgement call: SWWAF_IPV6_GROUP_PREFIX accepts 32 to 128, the issue's example range. Model: opus-5-5 --- README.md | 91 ++++++++++++++---------- internal/anomaly/anomaly.go | 6 +- internal/config/config.go | 50 +++++++++++++ internal/config/config_test.go | 62 ++++++++++++++++ internal/lookup/lookup.go | 3 +- internal/proxy/admin.go | 2 +- internal/proxy/bans.go | 8 +-- internal/proxy/bans_test.go | 7 +- internal/proxy/client.go | 12 ++-- internal/proxy/history_test.go | 18 +++++ internal/proxy/lookup.go | 4 +- internal/proxy/passthrough_test.go | 21 +++++- internal/proxy/proxy.go | 2 +- internal/proxy/proxy_test.go | 4 +- internal/proxy/ratelimits_test.go | 43 +++++++++++ internal/proxy/reputation.go | 4 +- internal/proxy/request.go | 8 +-- internal/ratelimit/history_test.go | 8 +-- internal/ratelimit/ratelimit.go | 17 +++-- internal/ratelimit/ratelimit_test.go | 47 +++++++----- internal/ratelimit/snapshot_test.go | 14 ++-- internal/requestlog/requestlog.go | 5 +- internal/requestlog/requestlog_test.go | 49 ++++++++++++- internal/smallwebwaf/smallwebwaf.go | 9 ++- internal/smallwebwaf/smallwebwaf_test.go | 48 +++++++++++++ internal/state/state_test.go | 2 +- 26 files changed, 439 insertions(+), 105 deletions(-) diff --git a/README.md b/README.md index fd004b8..3bec292 100644 --- a/README.md +++ b/README.md @@ -116,11 +116,12 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set, and the default rule file of `SWWAF_RATE_LIMIT_EXEMPT_PATHS`, as that setting below describes, is neither counted nor refused by the rate limits; the static lists, bans, the country lists and the rule files 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 + one IPv6 group, the netblock of `SWWAF_IPV6_GROUP_PREFIX` its address is in, a + /64 by default, 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). + window still covers. At most `SWWAF_MAX_TRACKED_CLIENTS` clients are kept, + 20,000 by default, the least recently seen dropped first, with their history, + and a restart gives no client a fresh allowance (see "State files" below). - Counts each client's bytes over a minute, an hour and a day, in the same way: once a request passed to the app has ended, the body bytes of its answer, of the request, or of both, as `SWWAF_BYTES_COUNT` says. For a WebSocket, or any @@ -153,8 +154,8 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set, and the default rule file of broken again within a day of a ban ending bans for three times as long as that ban, so 1, 3, 9, 27 and 81 hours; a ban that would last longer than seven days is permanent instead. A ban covers the client's netblock: its IPv4 address, or - the netblock around it that `SWWAF_BAN_SCOPE_V4_PREFIX` sets, or its IPv6 /64. - While it lasts, every request from the netblock is refused with + the netblock around it that `SWWAF_BAN_SCOPE_V4_PREFIX` sets, or its IPv6 + group. While it lasts, every request from the netblock is refused with `SWWAF_BAN_RESPONSE` after the static lists and before the country lists, so the client is not looked up, and is not counted for the rate limits. A ban sets the client's counters back to zero. Each ban carries notes for deciding @@ -315,7 +316,8 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set, and the default rule file of Each setting is an environment variable, or a file one names (see "Settings given as files" below), and each has a default, so none has to be set. A setting that is set but invalid stops the start with a message naming it, and the -effective settings are logged at start. +effective settings are logged at start, unless `SWWAF_LOG_LEVEL` is `warn` or +`error`, which hold that line back. - `SWWAF_LISTEN_ADDR` (default `:8080`): where `smallwebwaf` listens. - `SWWAF_UPSTREAM_URL` (default `http://127.0.0.1:8081`): the app, as `http` or @@ -333,6 +335,18 @@ effective settings are logged at start. - `SWWAF_TRUSTED_PROXIES` (default `10.0.0.0/8,172.16.0.0/12,192.168.0.0/16`, the private address ranges): the netblocks whose `X-Forwarded-For` is believed. A list given replaces the default; set but empty, it trusts nothing. +- `SWWAF_IPV6_GROUP_PREFIX` (default `64`): the length of an IPv6 client's + group, the netblock that is one client, from 32 to 128, since a shorter one + would make one client of the customers of several providers. The rate limits, + the byte limits, bans, the table of clients, the lookups, AbuseIPDB's scores + and the anomaly thresholds per client all take an IPv6 client as its group, + and `client_group` gives it. After it changes, each IPv6 client starts afresh: + what was kept of it under its earlier group, its counts, history, GeoJS answer + and AbuseIPDB score, is not used for it, while each ban keeps refusing its + netblock until it ends. +- `SWWAF_MAX_TRACKED_CLIENTS` (default `20000`): the most clients kept in memory + and in `clients.json`, with their counters and history, a whole number above + zero. Past it, the least recently seen is dropped first. - `SWWAF_CLIENT_REQUEST_TIMEOUT` (default `60s`): how long a client may take to send its request line and headers, and then, from the end of the headers, its body. @@ -510,7 +524,7 @@ effective settings are logged at start. kept, past, active and permanent. The bans you make or keep are kept besides. - `SWWAF_BAN_SCOPE_V4_PREFIX` (default `32`): the length of the netblock around an IPv4 client that a ban covers, such as `24` to ban the surrounding /24. An - IPv6 ban covers the client's /64. + IPv6 ban covers the client's group, as `SWWAF_IPV6_GROUP_PREFIX` sets it. - `SWWAF_STATE_DIR` (default `/var/lib/smallwebwaf`): the directory of the state files, an absolute path. A directory `smallwebwaf` cannot write stops the start. @@ -525,6 +539,10 @@ effective settings are logged at start. (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_LOG_LEVEL` (default `info`): the least severe of `smallwebwaf`'s own + messages that are written, on stdout and to the syslog server: `debug`, + `info`, `warn` or `error`. No message is at `debug` yet, so it writes what + `info` does. It holds back no line of the request log. - `SWWAF_ADMIN_TOKEN` (default unset): the token an admin sends for the ban endpoints and `/_smallwebwaf/clients/` (see "Admin endpoints" below), a long random value. While it is unset they are off; one shorter than 32 @@ -637,7 +655,8 @@ Percentages are whole numbers from 0 to 100, and an entry of a list of them is an AS number or a country, `:` and a percentage; an AS number or a country listed twice in one of them stops the start. `off` switches a timeout, a size limit, a rate limit, a byte limit, an anomaly threshold, `SWWAF_ALERT_COOLDOWN` -or `SWWAF_ALERT_MAX_PER_HOUR` off; `SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES`, +or `SWWAF_ALERT_MAX_PER_HOUR` off; `SWWAF_IPV6_GROUP_PREFIX`, +`SWWAF_MAX_TRACKED_CLIENTS`, `SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES`, `SWWAF_LOOKUP_TIMEOUT`, `SWWAF_UNKNOWN_LIMIT_PERCENT`, `SWWAF_BLOCKLIST_REFRESH`, `SWWAF_ABUSEIPDB_MIN_SCORE`, `SWWAF_ABUSEIPDB_DAILY_BUDGET`, `SWWAF_REPUTATION_CACHE_TTL`, @@ -645,12 +664,10 @@ or `SWWAF_ALERT_MAX_PER_HOUR` off; `SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES`, `SWWAF_METRICS_TOP_N`, `SWWAF_LOG_REMOTE_BUFFER`, `SWWAF_ANOMALY_NET_V4_PREFIX` and `SWWAF_ANOMALY_NET_V6_PREFIX` 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. At -most 100,000 answers from GeoJS are kept, for 7 days each, at most 20,000 -anomaly counters, at most 100,000 verdicts of the DNSBL zones, with at most -1,000 queries to them under way at once, and at most 100,000 scores of -AbuseIPDB. +Several limits are fixed rather than settings. At most 100,000 answers from +GeoJS are kept, for 7 days each, at most 20,000 anomaly counters, at most +100,000 verdicts of the DNSBL zones, with at most 1,000 queries to them under +way at once, and at most 100,000 scores of AbuseIPDB. ### Settings given as files @@ -707,7 +724,7 @@ which every line has. - `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. + a /32, or its IPv6 group, as `SWWAF_IPV6_GROUP_PREFIX` sets it. - `asn`, `as_name` and `country` are the client's AS number, such as `AS64496`, the name of that AS, and its country, as GeoJS or the lookup database gives them. Each is empty when `SWWAF_LOOKUP_SOURCE` is `off`, for a client in @@ -810,7 +827,8 @@ which every line has. 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"`, each with `instance` as a request's line has it. +`"type":"process"`, each with `instance` as a request's line has it, and those +less severe than `SWWAF_LOG_LEVEL` are not written. Go's HTTP server, on which `smallwebwaf` is built, reads a request's line and headers before `smallwebwaf` sees the request, and some requests end there, @@ -1078,9 +1096,10 @@ with times in UTC. zone gave it, `fetched`; and under `abuseipdb` (see "AbuseIPDB" below), the `day`, in UTC, whose checks it counts, left out before the first, the checks `spent` that day, and under `scores`, each score of AbuseIPDB still in use: - the `client`, its IPv4 address as a /32 or its IPv6 /64, its `score`, and when - AbuseIPDB gave it, `fetched`. As the file is read, the lists the settings no - longer name, and the verdicts of the zones they no longer name, are dropped. + the `client`, its IPv4 address as a /32 or its IPv6 group, its `score`, and + when AbuseIPDB gave it, `fetched`. As the file is read, the lists the settings + no longer name, and the verdicts of the zones they no longer name, are + dropped. - `alerts.json`: the state of the alerts (see "Alerts" above), indented to be read: under `cooldowns`, for each event and netblock, with the `source` too for a `reputation_hit`, or event and `file` or `source`, or for an `anomaly`, @@ -1379,7 +1398,7 @@ request that carries the token as `Authorization: Bearer `: `reason`. `netblock` is a netblock such as `203.0.113.0/24`, or a client's address, which bans the netblock a ban on that client covers: its IPv4 address, or the netblock around it that `SWWAF_BAN_SCOPE_V4_PREFIX` sets, or - its IPv6 /64. `duration` is a duration such as `1h` or `7d`, or `permanent`. + its IPv6 group. `duration` is a duration such as `1h` or `7d`, or `permanent`. The ban starts at once, its `cause` is `admin`, and it is made even while another ban on the netblock lasts. A body that is not such an object, has another field, has anything but whitespace after the object, or is longer than @@ -1660,7 +1679,7 @@ setting uses the answer, unless you set `SWWAF_LOOKUP_SOURCE=off`. The only visitors it is not told about are those in `SWWAF_ALLOW_NETS` or `SWWAF_DENY_NETS`, those whose netblock a ban covers, and those on a private, loopback or link-local address. An IPv6 visitor is asked about by the first -address of its /64. Each answer is kept for seven days, in memory and in +address of its IPv6 group. Each answer is kept for seven days, in memory and in `lookups.json`, so that it survives a restart, and a visitor whose answer is kept is not asked about again. @@ -1775,7 +1794,7 @@ request from it until the zone has answered. The name asked about is the one RFC `192.0.2.99` is asked about in `dnsbl.dronebl.org` as `99.2.0.192.dnsbl.dronebl.org`, or the 32 hex digits of an IPv6 address in reverse order, each followed by a dot. An IPv6 client is asked about by its own -address, not by its /64. +address, not by its IPv6 group. A zone that answers that the name does not exist, or has no address, does not list the client, and one that answers with an address in `127.0.0.0/8` lists it. @@ -1821,8 +1840,8 @@ While `SWWAF_ABUSEIPDB_KEY` holds the key of an AbuseIPDB account, `smallwebwaf` asks AbuseIPDB's check endpoint, `https://api.abuseipdb.com/api/v2/check`, for the abuse confidence score of a client's own address, from 0 to 100. It is unset by default, for the reason no blocklist is named, and since AbuseIPDB needs an -account. An IPv6 client, a /64, is checked by the address of the request that -has it checked, and its score is used for the whole /64, whichever of its +account. An IPv6 client, an IPv6 group, is checked by the address of the request +that has it checked, and its score is used for the whole group, whichever of its addresses sends, so that one client costs at most one check every `SWWAF_REPUTATION_CACHE_TTL`. @@ -1934,17 +1953,17 @@ given as files" above). checks. Besides the Go standard library, `github.com/hashicorp/golang-lru/v2` keeps the -table of clients to 20,000 and the GeoJS answers to 100,000, dropping the least -recently seen, the DNSBL zones' verdicts and AbuseIPDB's scores to 100,000 each, -dropping the one fetched longest ago, the anomaly counters to 20,000, dropping -the one counted least recently, and the banned netblocks in the order they were -last seen, from which the ledger picks the ban to drop past `SWWAF_MAX_BANS`, -and `github.com/prometheus/client_golang` keeps the metrics and serves them, and -`github.com/fsnotify/fsnotify` tells `smallwebwaf` when a state file or a rule -file is saved, or the lookup database replaced, and -`github.com/oschwald/maxminddb-golang/v2` reads the lookup database, which the -tests write with `github.com/maxmind/mmdbwriter`. The country codes are the list -in `internal/config/config.go`. +table of clients to `SWWAF_MAX_TRACKED_CLIENTS` and the GeoJS answers to +100,000, dropping the least recently seen, the DNSBL zones' verdicts and +AbuseIPDB's scores to 100,000 each, dropping the one fetched longest ago, the +anomaly counters to 20,000, dropping the one counted least recently, and the +banned netblocks in the order they were last seen, from which the ledger picks +the ban to drop past `SWWAF_MAX_BANS`, and `github.com/prometheus/client_golang` +keeps the metrics and serves them, and `github.com/fsnotify/fsnotify` tells +`smallwebwaf` when a state file or a rule file is saved, or the lookup database +replaced, and `github.com/oschwald/maxminddb-golang/v2` reads the lookup +database, which the tests write with `github.com/maxmind/mmdbwriter`. The +country codes are the list in `internal/config/config.go`. ## Entrypoints diff --git a/internal/anomaly/anomaly.go b/internal/anomaly/anomaly.go index de54cfb..f811eeb 100644 --- a/internal/anomaly/anomaly.go +++ b/internal/anomaly/anomaly.go @@ -27,7 +27,8 @@ const maxCounters = 20000 // The scopes, what a counter counts, as the settings, alerts.json and the // alerts name them. const ( - // ScopeClient is one client: an IPv4 address, or an IPv6 /64. + // ScopeClient is one client: an IPv4 address, or an IPv6 netblock of + // SWWAF_IPV6_GROUP_PREFIX. ScopeClient = "client" // ScopeNet is the netblock around a client, SWWAF_ANOMALY_NET_V4_PREFIX // or SWWAF_ANOMALY_NET_V6_PREFIX long. @@ -103,7 +104,8 @@ type Counter struct { // Request is a request that has ended, as the counters count it. type Request struct { // Client is the client's address, and ClientGroup the client it is - // counted as: its IPv4 address, or its IPv6 /64. + // counted as: its IPv4 address, or the IPv6 netblock of + // SWWAF_IPV6_GROUP_PREFIX its address is in. Client netip.Addr ClientGroup netip.Prefix // ASN, ASName and Country are the client's as looked up, each "" when diff --git a/internal/config/config.go b/internal/config/config.go index e1014bd..ddb6cf9 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -48,6 +48,12 @@ type Config struct { // TrustedProxies are the netblocks whose X-Forwarded-For is // believed (SWWAF_TRUSTED_PROXIES). TrustedProxies []netip.Prefix + // IPv6GroupPrefix is the length of the IPv6 netblock that is one client + // (SWWAF_IPV6_GROUP_PREFIX), from 32 to 128. + IPv6GroupPrefix int + // MaxTrackedClients is the most clients the table of clients holds, in + // memory and in clients.json (SWWAF_MAX_TRACKED_CLIENTS). + MaxTrackedClients int // ClientRequestTimeout bounds reading the whole request from the // client (SWWAF_CLIENT_REQUEST_TIMEOUT). ClientRequestTimeout time.Duration @@ -209,6 +215,9 @@ type Config struct { // LogRequestHeaders are the request headers whose values the request // log gives, in lower case (SWWAF_LOG_REQUEST_HEADERS). LogRequestHeaders []string + // LogLevel is the least severe of the process's own messages that are + // written (SWWAF_LOG_LEVEL). It holds back no request log line. + LogLevel slog.Level // AdminToken is the bearer token an admin sends for the ban endpoints // and /_smallwebwaf/clients/ (SWWAF_ADMIN_TOKEN), "" while it is // unset and they are off. @@ -297,6 +306,10 @@ const ( gibibyte = 1 << 30 ipv4Bits = 32 ipv6Bits = 128 + // minIPv6GroupPrefix is the shortest SWWAF_IPV6_GROUP_PREFIX, the + // netblock a provider is usually given: a shorter one would make one + // client of the customers of several providers. + minIPv6GroupPrefix = 32 // minTokenLength is the fewest characters a token may have. minTokenLength = 32 // masked is what the log shows for a token that is set, and in place of @@ -346,6 +359,9 @@ var ( "is not the length of an IPv4 netblock, from 0 to 32, such as 24") errNotV6Prefix = errors.New( "is not the length of an IPv6 netblock, from 0 to 128, such as 48") + errNotIPv6GroupPrefix = errors.New( + "is not the length of an IPv6 netblock, from 32 to 128, such as 64") + errNotLogLevel = errors.New("is not debug, info, warn or error") errNotNamedNetblock = errors.New( "is not a name, = and a netblock, such as office=203.0.113.0/24") errNotAbsolutePath = errors.New( @@ -411,6 +427,8 @@ func FromEnvironment(lookupEnv func(string) (string, bool)) (*Config, error) { InstanceName: env.instanceName(), Observe: env.observe("SWWAF_MODE", "enforce"), TrustedProxies: env.netblocks("SWWAF_TRUSTED_PROXIES", privateRanges), + IPv6GroupPrefix: env.ipv6GroupPrefix("SWWAF_IPV6_GROUP_PREFIX", "64"), + MaxTrackedClients: env.numberNotOff("SWWAF_MAX_TRACKED_CLIENTS", "20000"), ClientRequestTimeout: env.duration("SWWAF_CLIENT_REQUEST_TIMEOUT", "60s"), ClientRequestHeaderMaxBytes: env.headerSize( "SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES", "32K"), @@ -465,6 +483,7 @@ func FromEnvironment(lookupEnv func(string) (string, bool)) (*Config, error) { StateCounterInterval: env.durationNotOff("SWWAF_STATE_COUNTER_INTERVAL", "15m"), LogRequestHeaders: env.headerNames("SWWAF_LOG_REQUEST_HEADERS", "accept,accept-language,accept-encoding,content-type,origin,range"), + LogLevel: env.logLevel("SWWAF_LOG_LEVEL", "info"), AdminToken: env.token("SWWAF_ADMIN_TOKEN"), MetricsToken: env.token("SWWAF_METRICS_TOKEN"), MetricsTopN: env.numberNotOff("SWWAF_METRICS_TOP_N", "50"), @@ -944,6 +963,37 @@ func (e *environment) v6Prefix(name, defaultValue string) int { return length } +// ipv6GroupPrefix reads the setting that is the length of the IPv6 +// netblock that is one client, from minIPv6GroupPrefix to 128. +func (e *environment) ipv6GroupPrefix(name, defaultValue string) int { + value := e.value(name, defaultValue) + + length, err := strconv.Atoi(value) + if err != nil || length < minIPv6GroupPrefix || length > ipv6Bits { + e.check(name, fmt.Errorf("%q %w", value, errNotIPv6GroupPrefix)) + } + + return length +} + +// logLevel reads the setting that is the least severe of the process's +// own messages that are written: debug, info, warn or error. +func (e *environment) logLevel(name, defaultValue string) slog.Level { + value := e.value(name, defaultValue) + + level, known := map[string]slog.Level{ + "debug": slog.LevelDebug, + "info": slog.LevelInfo, + "warn": slog.LevelWarn, + "error": slog.LevelError, + }[value] + if !known { + e.check(name, fmt.Errorf("%q %w", value, errNotLogLevel)) + } + + return level +} + // thresholds reads the four anomaly thresholds whose settings' names // start with prefix: requests and bytes per minute and per hour. Each is // off by default. diff --git a/internal/config/config_test.go b/internal/config/config_test.go index 62ce931..5ec0344 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -27,6 +27,8 @@ const ( upstreamURL = "SWWAF_UPSTREAM_URL" mode = "SWWAF_MODE" trustedProxies = "SWWAF_TRUSTED_PROXIES" + ipv6GroupPrefix = "SWWAF_IPV6_GROUP_PREFIX" + maxTrackedClients = "SWWAF_MAX_TRACKED_CLIENTS" clientRequestTimeout = "SWWAF_CLIENT_REQUEST_TIMEOUT" clientHeaderMaxBytes = "SWWAF_CLIENT_REQUEST_HEADER_MAX_BYTES" clientIdleTimeout = "SWWAF_CLIENT_IDLE_TIMEOUT" @@ -84,6 +86,7 @@ const ( metricsTopN = "SWWAF_METRICS_TOP_N" instanceName = "SWWAF_INSTANCE_NAME" logRequestHeaders = "SWWAF_LOG_REQUEST_HEADERS" + logLevel = "SWWAF_LOG_LEVEL" rulesDir = "SWWAF_RULES_DIR" rulesEnabled = "SWWAF_RULES_ENABLED" logRemoteURL = "SWWAF_LOG_REMOTE_URL" @@ -399,6 +402,57 @@ func TestValuesAsSet(t *testing.T) { wantCountries(t, allowedCountries, cfg.ExclusivelyAllowedCountries, "DE") } +func TestIPv6GroupPrefixMaxTrackedClientsAndLogLevel(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + env environment + prefix, clients int + level slog.Level + }{ + {environment{}, 64, 20000, slog.LevelInfo}, + { + environment{ipv6GroupPrefix: "48", maxTrackedClients: "500", logLevel: "warn"}, + 48, 500, slog.LevelWarn, + }, + } { + cfg := fromEnvironment(t, tc.env) + if cfg.IPv6GroupPrefix != tc.prefix || cfg.MaxTrackedClients != tc.clients || + cfg.LogLevel != tc.level { + t.Errorf("%v gave %d, %d and %v, want %d, %d and %v", tc.env, + cfg.IPv6GroupPrefix, cfg.MaxTrackedClients, cfg.LogLevel, + tc.prefix, tc.clients, tc.level) + } + } +} + +func TestIPv6GroupPrefixFrom32To128(t *testing.T) { + t.Parallel() + + for _, length := range []int{32, 128} { + cfg := fromEnvironment(t, environment{ipv6GroupPrefix: strconv.Itoa(length)}) + if cfg.IPv6GroupPrefix != length { + t.Errorf("%s=%d gave %d", ipv6GroupPrefix, length, cfg.IPv6GroupPrefix) + } + } +} + +func TestEachLogLevel(t *testing.T) { + t.Parallel() + + for value, want := range map[string]slog.Level{ + "debug": slog.LevelDebug, + "info": slog.LevelInfo, + "warn": slog.LevelWarn, + "error": slog.LevelError, + } { + cfg := fromEnvironment(t, environment{logLevel: value}) + if cfg.LogLevel != want { + t.Errorf("%s=%s gave %v, want %v", logLevel, value, cfg.LogLevel, want) + } + } +} + func TestByteLimitSettingsAsSet(t *testing.T) { t.Parallel() @@ -1698,6 +1752,10 @@ func TestInvalidValueStopsTheStart(t *testing.T) { {trustedProxies, "traefik"}, {trustedProxies, "10.0.0.0/8,,192.168.0.0/16"}, {trustedProxies, "fe80::1%eth0"}, + {ipv6GroupPrefix, "31"}, {ipv6GroupPrefix, "129"}, {ipv6GroupPrefix, "/64"}, + {ipv6GroupPrefix, off}, {ipv6GroupPrefix, ""}, + {maxTrackedClients, "0"}, {maxTrackedClients, "-1"}, {maxTrackedClients, off}, + {maxTrackedClients, "20K"}, {allowNets, "192.0.2.0/24,monitoring"}, {rateLimitExemptNets, "2001:db8::/129"}, {denyNets, "198.51.100.0/24,"}, @@ -1751,6 +1809,7 @@ func TestInvalidValueStopsTheStart(t *testing.T) { {logRequestHeaders, "accept language"}, {logRequestHeaders, "x-foo:"}, {logRequestHeaders, "host"}, {logRequestHeaders, "accept,Host"}, {logRequestHeaders, "transfer-encoding"}, {logRequestHeaders, "TRANSFER-ENCODING"}, + {logLevel, "INFO"}, {logLevel, "warning"}, {logLevel, "trace"}, {logLevel, ""}, {rulesEnabled, "yes"}, {rulesEnabled, "True"}, }) } @@ -1993,6 +2052,8 @@ func TestLogsEachSettingWithItsValue(t *testing.T) { upstreamURL: "http://127.0.0.1:8081", mode: "enforce", trustedProxies: "10.0.0.0/8,172.16.0.0/12,192.168.0.0/16", + ipv6GroupPrefix: "64", + maxTrackedClients: "20000", clientRequestTimeout: "45s", clientHeaderMaxBytes: "32K", clientIdleTimeout: "120s", @@ -2050,6 +2111,7 @@ func TestLogsEachSettingWithItsValue(t *testing.T) { metricsTopN: "50", instanceName: hostname, logRequestHeaders: defaultLogRequestHeaders, + logLevel: "info", rulesDir: "/etc/smallwebwaf/rules.d", rulesEnabled: "true", logRemoteURL: "", diff --git a/internal/lookup/lookup.go b/internal/lookup/lookup.go index b4b5006..cdd86cb 100644 --- a/internal/lookup/lookup.go +++ b/internal/lookup/lookup.go @@ -176,7 +176,8 @@ func New(params Params) *GeoJS { // when it ends. // // GeoJS is asked about the client's first address, which is the client's -// own address for IPv4, and an address in the same place for an IPv6 /64. +// own address for IPv4, and an address in the same place for an IPv6 +// netblock. func (g *GeoJS) LookUp(ctx context.Context, client netip.Prefix) Answer { answer, asked := g.answerOrWait(ctx, client) if asked == nil { diff --git a/internal/proxy/admin.go b/internal/proxy/admin.go index fe4a12d..5db184d 100644 --- a/internal/proxy/admin.go +++ b/internal/proxy/admin.go @@ -282,7 +282,7 @@ func (rq *request) showClient() { answer := clientAnswer{Bans: state.BanEntries(rq.h.ledger.Covering(addr))} - client, seen := rq.h.limiter.Client(clientGroup(addr)) + client, seen := rq.h.limiter.Client(rq.h.clientGroup(addr)) if seen { answer.Client = &client } diff --git a/internal/proxy/bans.go b/internal/proxy/bans.go index 95f889a..d56b066 100644 --- a/internal/proxy/bans.go +++ b/internal/proxy/bans.go @@ -45,7 +45,7 @@ func (rq *request) banned(now time.Time) bool { // the client over a rate limit, as its limit percentage lowers it, which // breaks it. func (rq *request) limitBroken(now time.Time) bool { - counts, hit, over := rq.h.limiter.Count(clientGroup(rq.client), now, + counts, hit, over := rq.h.limiter.Count(rq.h.clientGroup(rq.client), now, rq.limitPercent.percent) rq.line.Counts = counts @@ -71,7 +71,7 @@ func (rq *request) countBytes() { now := rq.h.now() - counts, hit, over := rq.h.limiter.CountBytes(clientGroup(rq.client), now, + counts, hit, over := rq.h.limiter.CountBytes(rq.h.clientGroup(rq.client), now, rq.countedBytes(), rq.bytesPercent.percent) rq.line.Counts.MinuteBytes = counts.MinuteBytes rq.line.Counts.HourBytes = counts.HourBytes @@ -155,7 +155,7 @@ func (rq *request) banForLimit(now time.Time, hit ratelimit.Hit, status int) { } ban, made := rq.h.ledger.BanForLimit(netblock, now, notes) - rq.h.limiter.Reset(clientGroup(rq.client)) + rq.h.limiter.Reset(rq.h.clientGroup(rq.client)) rq.line.BanExpires = banExpires(ban) if made { @@ -276,7 +276,7 @@ func (h *handler) netblock(client netip.Addr) netip.Prefix { return netip.PrefixFrom(addr, h.config.BanScopeV4Prefix).Masked() } - return clientGroup(addr) + return h.clientGroup(addr) } // banExpires is when ban ends, as the log line gives it: a time, or diff --git a/internal/proxy/bans_test.go b/internal/proxy/bans_test.go index 824d01c..03926cc 100644 --- a/internal/proxy/bans_test.go +++ b/internal/proxy/bans_test.go @@ -165,9 +165,14 @@ func TestBanCoversTheClientsNetblock(t *testing.T) { []string{otherClient, exempt}, []string{"203.0.112.9", allowed}, }, { - "an IPv6 /64", nil, "2001:db8:5::1", + "an IPv6 /64, by default", nil, "2001:db8:5::1", []string{"2001:db8:5::ffff:1"}, []string{"2001:db8:5:1::1"}, }, + { + "the IPv6 netblock SWWAF_IPV6_GROUP_PREFIX sets", + map[string]string{ipv6GroupPrefix: "48"}, "2001:db8:7::1", + []string{"2001:db8:7:ffff::1"}, []string{"2001:db8:8::1"}, + }, } { t.Run(tc.name, func(t *testing.T) { t.Parallel() diff --git a/internal/proxy/client.go b/internal/proxy/client.go index 11058b9..e725973 100644 --- a/internal/proxy/client.go +++ b/internal/proxy/client.go @@ -76,16 +76,14 @@ func scheme(r *http.Request, peerTrusted bool) string { return proto } -// ipv6GroupPrefix is the length of the IPv6 netblock that is one client. -const ipv6GroupPrefix = 64 - // clientGroup is the client a request is counted toward: its IPv4 -// address, or the /64 its IPv6 address is in, since one abuser usually -// holds a whole /64. An IPv4 address in IPv6 form counts as IPv4. -func clientGroup(addr netip.Addr) netip.Prefix { +// address, or its IPv6 group, the netblock its IPv6 address is in of the +// length SWWAF_IPV6_GROUP_PREFIX sets, a /64 by default, since one abuser +// usually holds a whole /64. An IPv4 address in IPv6 form counts as IPv4. +func (h *handler) clientGroup(addr netip.Addr) netip.Prefix { addr = addr.Unmap() if addr.Is6() { - return netip.PrefixFrom(addr, ipv6GroupPrefix).Masked() + return netip.PrefixFrom(addr, h.config.IPv6GroupPrefix).Masked() } return netip.PrefixFrom(addr, addr.BitLen()) diff --git a/internal/proxy/history_test.go b/internal/proxy/history_test.go index c2104e2..7514c59 100644 --- a/internal/proxy/history_test.go +++ b/internal/proxy/history_test.go @@ -56,6 +56,24 @@ func TestHistoryKeepsEachRequestOfTheClient(t *testing.T) { } } +func TestTableOfClientsHoldsAtMostMaxTrackedClients(t *testing.T) { + t.Parallel() + + s, _, server := startWithClock(t, "", map[string]string{maxTrackedClients: "2"}) + + // The third client drops the least recently seen, the first, with its + // history. + for _, from := range []string{"192.0.2.1", "192.0.2.2", "192.0.2.3"} { + s.get(from, http.StatusOK, requestlog.ActionForward) + } + + _, held := server.Limiter.Client(netip.MustParsePrefix("192.0.2.1/32")) + if server.Limiter.Len() != 2 || held { + t.Errorf("the table holds %d clients, the first among them: %t; want 2, "+ + "without it", server.Limiter.Len(), held) + } +} + func TestHistoryCountsTheBodiesEachWay(t *testing.T) { t.Parallel() diff --git a/internal/proxy/lookup.go b/internal/proxy/lookup.go index 352e71d..33190e4 100644 --- a/internal/proxy/lookup.go +++ b/internal/proxy/lookup.go @@ -31,9 +31,9 @@ func (rq *request) lookUp(ctx context.Context) { } if rq.h.config.LookupSource == "file" { - rq.lookupAnswer = rq.h.lookupFile.LookUp(clientGroup(rq.client)) + rq.lookupAnswer = rq.h.lookupFile.LookUp(rq.h.clientGroup(rq.client)) } else { - rq.lookupAnswer = rq.h.geojs.LookUp(ctx, clientGroup(rq.client)) + rq.lookupAnswer = rq.h.geojs.LookUp(ctx, rq.h.clientGroup(rq.client)) } rq.lookedUp = true diff --git a/internal/proxy/passthrough_test.go b/internal/proxy/passthrough_test.go index 0399cc1..aade4f6 100644 --- a/internal/proxy/passthrough_test.go +++ b/internal/proxy/passthrough_test.go @@ -320,7 +320,7 @@ func TestServerHasTheDefaultLimits(t *testing.T) { server := proxy.New(proxy.Params{ Config: cfg, RequestLog: io.Discard, - ProcessLog: requestlog.NewProcessLogger(io.Discard, cfg.InstanceName), + ProcessLog: requestlog.NewProcessLogger(io.Discard, cfg.InstanceName, cfg.LogLevel), }) if server.Addr != ":8080" || server.MaxHeaderBytes != 28<<10 || @@ -399,6 +399,25 @@ func TestAnswers502WhenTheAppCannotBeReached(t *testing.T) { } } +func TestLogLevelHoldsBackNoRequestLine(t *testing.T) { + t.Parallel() + + // At error the warning that the request to the app failed is held back, + // and is written before the answer is. + addr, out := startProxy(t, "http://"+localhost+":1", map[string]string{ + "SWWAF_LOG_LEVEL": "error", + }) + + wantStatus(t, get(t, addr, "/"), http.StatusBadGateway) + wantLine(t, out.requestLine(t), http.StatusBadGateway, requestlog.ActionUpstreamError) + + for _, line := range out.lines(t) { + if line["type"] == "process" { + t.Errorf("process line %v, want none at error", line) + } + } +} + func TestLogsAnAnswerThatBrokeOff(t *testing.T) { t.Parallel() diff --git a/internal/proxy/proxy.go b/internal/proxy/proxy.go index 1bca56d..1298343 100644 --- a/internal/proxy/proxy.go +++ b/internal/proxy/proxy.go @@ -124,7 +124,7 @@ func New(params Params) *Server { BytesPerMinute: params.Config.BytesLimitPerMinute, BytesPerHour: params.Config.BytesLimitPerHour, BytesPerDay: params.Config.BytesLimitPerDay, - }), + }, params.Config.MaxTrackedClients), ledger: bans.New(bans.Rules{ LimitBanDuration: params.Config.LimitBanDuration, LimitBanRepeatWindow: params.Config.LimitBanRepeatWindow, diff --git a/internal/proxy/proxy_test.go b/internal/proxy/proxy_test.go index a83988d..77a3c42 100644 --- a/internal/proxy/proxy_test.go +++ b/internal/proxy/proxy_test.go @@ -61,6 +61,8 @@ const ( requestMaxBytes = "SWWAF_REQUEST_MAX_BYTES" responseMaxBytes = "SWWAF_RESPONSE_MAX_BYTES" trustedProxies = "SWWAF_TRUSTED_PROXIES" + ipv6GroupPrefix = "SWWAF_IPV6_GROUP_PREFIX" + maxTrackedClients = "SWWAF_MAX_TRACKED_CLIENTS" allowNets = "SWWAF_ALLOW_NETS" rateLimitExemptNets = "SWWAF_RATE_LIMIT_EXEMPT_NETS" denyNets = "SWWAF_DENY_NETS" @@ -295,7 +297,7 @@ func newProxy( } out := &output{} - processLog := requestlog.NewProcessLogger(out, cfg.InstanceName) + processLog := requestlog.NewProcessLogger(out, cfg.InstanceName, cfg.LogLevel) ruleFiles, err := rules.Load(rules.Params{ Dir: cfg.RulesDir, Enabled: cfg.RulesEnabled, ProcessLog: processLog, diff --git a/internal/proxy/ratelimits_test.go b/internal/proxy/ratelimits_test.go index d133f2a..5d7408e 100644 --- a/internal/proxy/ratelimits_test.go +++ b/internal/proxy/ratelimits_test.go @@ -72,6 +72,49 @@ func TestRateLimitRefusesBeforeTheApp(t *testing.T) { } } +func TestIPv6GroupPrefixSetsTheClientTheLimitsCount(t *testing.T) { + t.Parallel() + + // With SWWAF_IPV6_GROUP_PREFIX at 48, the first two addresses, in two + // /64s of one /48, are one client, and the second's request breaks the + // limit; the third, in the next /48, is another client. + const ( + first = "2001:db8:9::1" + second = "2001:db8:9:1::1" + other = "2001:db8:a::1" + ) + + for _, tc := range []struct { + setting, value string + // status and action are those of the request that breaks the + // limit: a rate limit refuses it, a byte limit passes it on. + status int + action string + }{ + {rateLimitPerMinute, "1", http.StatusForbidden, requestlog.ActionRateLimited}, + {bytesLimitPerMinute, byteLimit, http.StatusOK, requestlog.ActionForward}, + } { + t.Run(tc.setting, func(t *testing.T) { + t.Parallel() + + s, _ := startWithAnswers(t, map[string]string{ + ipv6GroupPrefix: "48", tc.setting: tc.value, + }) + + s.get(first, http.StatusOK, requestlog.ActionForward) + + line := s.get(second, tc.status, tc.action) + if line.ClientGroup != "2001:db8:9::/48" || + line.Offence != requestlog.OffenceLimit { + t.Errorf("log line has client_group %q and offence %q, "+ + "want 2001:db8:9::/48 and limit", line.ClientGroup, line.Offence) + } + + s.get(other, http.StatusOK, requestlog.ActionForward) + }) + } +} + func TestRateLimitExemptPathsAreNeitherCountedNorRefused(t *testing.T) { t.Parallel() diff --git a/internal/proxy/reputation.go b/internal/proxy/reputation.go index b7770d0..d1439b5 100644 --- a/internal/proxy/reputation.go +++ b/internal/proxy/reputation.go @@ -52,7 +52,7 @@ func (rq *request) abuseIPDBDenied(ctx context.Context) bool { return false } - client := clientGroup(rq.client) + client := rq.h.clientGroup(rq.client) held, _ := rq.h.limiter.Client(client) offender := held.History.Offences != ratelimit.Offences{} @@ -88,7 +88,7 @@ func (rq *request) noteHit(source, reason string, detail map[string]any) { rq.h.alerts.Raise(alerts.Alert{ Event: alerts.EventReputationHit, Client: rq.client, - Netblock: clientGroup(rq.client), + Netblock: rq.h.clientGroup(rq.client), ASN: rq.line.ASN, ASName: rq.line.ASName, Country: rq.line.Country, diff --git a/internal/proxy/request.go b/internal/proxy/request.go index 1b44749..293abd3 100644 --- a/internal/proxy/request.go +++ b/internal/proxy/request.go @@ -140,7 +140,7 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request { RequestID: requestID(r, peerTrusted), PeerIP: peer.String(), ForwardedFor: strings.Join(forwardedFor, ", "), - ClientGroup: clientGroup(client).String(), + ClientGroup: h.clientGroup(client).String(), ContentType: r.Header.Get("Content-Type"), RequestHeaders: requestHeaders(r, h.config.LogRequestHeaders), HasAuthorization: len(r.Header.Values("Authorization")) > 0, @@ -539,7 +539,7 @@ func timing(start, end time.Time) *float64 { func (rq *request) addToHistory() { forwarded := !rq.upstreamStart.IsZero() - rq.h.limiter.AddToHistory(clientGroup(rq.client), rq.h.now(), ratelimit.Request{ + rq.h.limiter.AddToHistory(rq.h.clientGroup(rq.client), rq.h.now(), ratelimit.Request{ Forwarded: forwarded, Refused: !forwarded && rq.refused.Load() != nil, Status: rq.out.status, @@ -572,7 +572,7 @@ func (rq *request) countAnomalies() { rq.h.anomalies.Count(rq.h.now(), anomaly.Request{ Client: rq.client, - ClientGroup: clientGroup(rq.client), + ClientGroup: rq.h.clientGroup(rq.client), ASN: answer.ASN, ASName: answer.ASName, Country: answer.Country, @@ -601,7 +601,7 @@ func (rq *request) answerAtTheEnd() (lookup.Answer, bool) { return rq.lookupAnswer, true } - return rq.h.geojs.Kept(clientGroup(rq.client)) + return rq.h.geojs.Kept(rq.h.clientGroup(rq.client)) } // requestBytes is how many bytes of the request's body have been read. diff --git a/internal/ratelimit/history_test.go b/internal/ratelimit/history_test.go index b3af169..bd6bf05 100644 --- a/internal/ratelimit/history_test.go +++ b/internal/ratelimit/history_test.go @@ -11,7 +11,7 @@ import ( func TestHistoryKeepsEveryRequest(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -53,7 +53,7 @@ func TestHistoryKeepsEveryRequest(t *testing.T) { func TestLookupReachesTheHistoryOfAClientInTheTable(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") other := netip.MustParsePrefix("198.51.100.7/32") start := midnight() @@ -90,7 +90,7 @@ func TestLookupReachesTheHistoryOfAClientInTheTable(t *testing.T) { func TestResetKeepsTheHistory(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -109,7 +109,7 @@ func TestResetKeepsTheHistory(t *testing.T) { func TestRequestsAddsUpTheClientsInsideTheNetblock(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, tableSize) for client, requests := range map[string]int{ "198.51.100.9/32": 2, diff --git a/internal/ratelimit/ratelimit.go b/internal/ratelimit/ratelimit.go index 0e68a18..2862b79 100644 --- a/internal/ratelimit/ratelimit.go +++ b/internal/ratelimit/ratelimit.go @@ -2,8 +2,9 @@ // and bytes counted over a minute, an hour and a day, as the "Counting // method" section of SPEC.md describes, which tell when a request takes // the client over a rate limit or a byte limit, and each client's history -// since it was first seen. At most 20,000 clients are kept, in memory, and -// written to clients.json and read from it by the state package. +// since it was first seen. At most SWWAF_MAX_TRACKED_CLIENTS clients are +// kept, in memory, and written to clients.json and read from it by the +// state package. package ratelimit import ( @@ -16,11 +17,6 @@ import ( "github.com/hashicorp/golang-lru/v2/simplelru" ) -// maxClients is how many clients are kept. Past it, the least recently -// seen client is dropped, with its history, and starts afresh if it comes -// back. -const maxClients = 20000 - const day = 24 * time.Hour // The kinds of limits, as the metrics name them. @@ -150,8 +146,11 @@ type Request struct { RuleBlocked bool } -// New returns a Limiter for limits, with no client counted yet. -func New(limits Limits) *Limiter { +// New returns a Limiter for limits, with no client counted yet, whose +// table holds at most maxClients clients (SWWAF_MAX_TRACKED_CLIENTS). Past +// it, the least recently seen client is dropped, with its history, and +// starts afresh if it comes back. +func New(limits Limits, maxClients int) *Limiter { clients, err := simplelru.NewLRU[netip.Prefix, *Client](maxClients, nil) if err != nil { panic(err) // NewLRU fails only for a size below one diff --git a/internal/ratelimit/ratelimit_test.go b/internal/ratelimit/ratelimit_test.go index 0a31086..a6c20a7 100644 --- a/internal/ratelimit/ratelimit_test.go +++ b/internal/ratelimit/ratelimit_test.go @@ -12,6 +12,10 @@ import ( // limit is the limit the tests set. const limit = 3 +// tableSize is the most clients the tests' tables hold, the default of +// SWWAF_MAX_TRACKED_CLIENTS. +const tableSize = 20000 + // whole is the percentage of each limit a client gets when nothing lowers // its limits. const whole = 100 @@ -37,7 +41,7 @@ func TestEachWindowRefusesAtItsLimitAndLetsTheClientBack(t *testing.T) { t.Run(tc.window, func(t *testing.T) { t.Parallel() - limiter := ratelimit.New(tc.limits) + limiter := ratelimit.New(tc.limits, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() quarter := tc.length / 4 @@ -62,7 +66,7 @@ func TestEachWindowRefusesAtItsLimitAndLetsTheClientBack(t *testing.T) { func TestHitGivesTheLimitAndTheRequestsCounted(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit, PerHour: limit}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit, PerHour: limit}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -88,7 +92,8 @@ func TestHitGivesTheLimitAndTheRequestsCounted(t *testing.T) { func TestClientGetsItsPercentageOfEachLimitRoundedDown(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerMinute: 5, BytesPerDay: math.MaxInt64}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: 5, BytesPerDay: math.MaxInt64}, + tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -119,7 +124,8 @@ func TestZeroPercentIsAZeroAllowanceAndALimitOffStaysOff(t *testing.T) { t.Parallel() // Only the hour has limits: the minute's and the day's are off. - limiter := ratelimit.New(ratelimit.Limits{PerHour: limit, BytesPerHour: 1000}) + limiter := ratelimit.New(ratelimit.Limits{PerHour: limit, BytesPerHour: 1000}, + tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -156,7 +162,7 @@ func TestEachByteLimitIsBrokenByTheBytesCounted(t *testing.T) { t.Run(tc.window, func(t *testing.T) { t.Parallel() - limiter := ratelimit.New(tc.limits) + limiter := ratelimit.New(tc.limits, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") // 600 bytes are within the limit, 600 more over it. @@ -180,7 +186,8 @@ func TestEachByteLimitIsBrokenByTheBytesCounted(t *testing.T) { func TestALimitIsBrokenOnlyByWhatIsAddedToIt(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerMinute: 2, BytesPerMinute: 1000}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: 2, BytesPerMinute: 1000}, + tableSize) client := netip.MustParsePrefix("203.0.113.9/32") other := netip.MustParsePrefix("203.0.113.10/32") start := midnight() @@ -204,7 +211,7 @@ func TestALimitIsBrokenOnlyByWhatIsAddedToIt(t *testing.T) { func TestCountGivesTheBytesInEachWindow(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -230,7 +237,7 @@ func TestCountGivesTheBytesInEachWindow(t *testing.T) { func TestResetSetsTheBytesBackToZero(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{BytesPerDay: 1000}) + limiter := ratelimit.New(ratelimit.Limits{BytesPerDay: 1000}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -244,7 +251,7 @@ func TestResetSetsTheBytesBackToZero(t *testing.T) { func TestCountGivesTheRequestsInEachWindow(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -267,7 +274,7 @@ func TestCountGivesTheRequestsInEachWindow(t *testing.T) { func TestResetSetsTheCountsBackToZero(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit, PerDay: limit}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit, PerDay: limit}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -289,7 +296,7 @@ func TestResetSetsTheCountsBackToZero(t *testing.T) { func TestClientBackAfterAWholeBucketIsWithinTheLimitAtOnce(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerHour: limit}) + limiter := ratelimit.New(ratelimit.Limits{PerHour: limit}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -308,7 +315,8 @@ func TestClientBackAfterAWholeBucketIsWithinTheLimitAtOnce(t *testing.T) { func TestRefusedRequestsCount(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit, PerHour: 2 * limit}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit, PerHour: 2 * limit}, + tableSize) refused := netip.MustParsePrefix("203.0.113.9/32") within := netip.MustParsePrefix("203.0.113.10/32") start := midnight() @@ -341,7 +349,7 @@ func TestRefusedRequestsCount(t *testing.T) { func TestRequestCountedLateGoesInTheBucketUnderWay(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: limit}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -357,7 +365,7 @@ func TestRequestCountedLateGoesInTheBucketUnderWay(t *testing.T) { func TestClockSetBackStartsTheBucketsAfresh(t *testing.T) { t.Parallel() - limiter := ratelimit.New(ratelimit.Limits{PerHour: limit}) + limiter := ratelimit.New(ratelimit.Limits{PerHour: limit}, tableSize) client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() @@ -380,12 +388,12 @@ func TestClockSetBackStartsTheBucketsAfresh(t *testing.T) { wantCount(t, limiter, client, setBack, hour) } -func TestKeepsAtMost20000ClientsDroppingTheLeastRecentlySeen(t *testing.T) { +func TestKeepsAtMostMaxClientsDroppingTheLeastRecentlySeen(t *testing.T) { t.Parallel() - const maxClients = 20000 + const maxClients = 3 - limiter := ratelimit.New(ratelimit.Limits{PerMinute: 1}) + limiter := ratelimit.New(ratelimit.Limits{PerMinute: 1}, maxClients) now := midnight() clients := make([]netip.Prefix, maxClients+1) @@ -407,6 +415,11 @@ func TestKeepsAtMost20000ClientsDroppingTheLeastRecentlySeen(t *testing.T) { // One client more drops the least recently seen, the second, which // starts afresh, while the first is kept. wantCount(t, limiter, clients[maxClients], now, "") + + if limiter.Len() != maxClients { + t.Errorf("the table holds %d clients, want %d", limiter.Len(), maxClients) + } + wantCount(t, limiter, clients[1], now, "") wantCount(t, limiter, clients[0], now, minute) } diff --git a/internal/ratelimit/snapshot_test.go b/internal/ratelimit/snapshot_test.go index 56d2d45..01a2ba9 100644 --- a/internal/ratelimit/snapshot_test.go +++ b/internal/ratelimit/snapshot_test.go @@ -14,7 +14,7 @@ func TestSnapshotListsTheClientsByAddress(t *testing.T) { want := []string{"192.0.2.1/32", "203.0.113.9/32", "203.0.113.10/32", "2001:db8::/64"} - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, tableSize) for _, i := range []int{2, 3, 0, 1} { limiter.Count(netip.MustParsePrefix(want[i]), midnight(), whole) } @@ -43,7 +43,7 @@ func TestLoadedCountsCarryOn(t *testing.T) { client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() - before := ratelimit.New(ratelimit.Limits{PerHour: limit}) + before := ratelimit.New(ratelimit.Limits{PerHour: limit}, tableSize) for range limit { wantCount(t, before, client, start, "") } @@ -51,7 +51,7 @@ func TestLoadedCountsCarryOn(t *testing.T) { // Loaded into a new limiter, as across a restart, the client has no // fresh allowance. later := start.Add(time.Minute) - after := ratelimit.New(ratelimit.Limits{PerHour: limit}) + after := ratelimit.New(ratelimit.Limits{PerHour: limit}, tableSize) after.Load(before.Snapshot(), later) wantCount(t, after, client, later, hour) } @@ -62,7 +62,7 @@ func TestLoadEmptiesBucketsWhoseTimeHasPassed(t *testing.T) { client := netip.MustParsePrefix("203.0.113.9/32") start := midnight() - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, tableSize) limiter.Count(client, start, whole) limiter.CountBytes(client, start, 5, whole) limiter.AddToHistory(client, start, ratelimit.Request{Forwarded: true}) @@ -70,7 +70,7 @@ func TestLoadEmptiesBucketsWhoseTimeHasPassed(t *testing.T) { loaded := func(now time.Time) ratelimit.Client { t.Helper() - after := ratelimit.New(ratelimit.Limits{}) + after := ratelimit.New(ratelimit.Limits{}, tableSize) after.Load(limiter.Snapshot(), now) return after.Snapshot()[0] @@ -102,7 +102,7 @@ func TestLoadEmptiesBucketsWhoseTimeHasPassed(t *testing.T) { func TestLoadDropsTheLeastRecentlySeenFirst(t *testing.T) { t.Parallel() - const maxClients = 20000 + const maxClients = 3 // clients.json lists the clients by address. Here each was last seen // a second before the one listed before it, so the last listed is the @@ -116,7 +116,7 @@ func TestLoadDropsTheLeastRecentlySeenFirst(t *testing.T) { addr = addr.Next() } - limiter := ratelimit.New(ratelimit.Limits{}) + limiter := ratelimit.New(ratelimit.Limits{}, maxClients) limiter.Load(clients, midnight()) got := limiter.Snapshot() diff --git a/internal/requestlog/requestlog.go b/internal/requestlog/requestlog.go index 523be75..3c8be5d 100644 --- a/internal/requestlog/requestlog.go +++ b/internal/requestlog/requestlog.go @@ -193,8 +193,11 @@ func Milliseconds(d time.Duration) float64 { // NewProcessLogger returns the logger for the process's own messages: // JSON lines on w, marked "type":"process", with the time in the same form // as a request line's, and instanceName, SWWAF_INSTANCE_NAME, as instance. -func NewProcessLogger(w io.Writer, instanceName string) *slog.Logger { +// It writes only the messages at level, SWWAF_LOG_LEVEL, or more severe; +// the request lines Write writes are never held back. +func NewProcessLogger(w io.Writer, instanceName string, level slog.Level) *slog.Logger { handler := slog.NewJSONHandler(w, &slog.HandlerOptions{ + Level: level, ReplaceAttr: func(groups []string, attr slog.Attr) slog.Attr { if attr.Key == slog.TimeKey && len(groups) == 0 { return slog.String(slog.TimeKey, FormatTime(attr.Value.Time())) diff --git a/internal/requestlog/requestlog_test.go b/internal/requestlog/requestlog_test.go index eae737e..9824b67 100644 --- a/internal/requestlog/requestlog_test.go +++ b/internal/requestlog/requestlog_test.go @@ -3,6 +3,8 @@ package requestlog_test import ( "bytes" "encoding/json" + "log/slog" + "slices" "strings" "testing" "time" @@ -70,7 +72,8 @@ func TestProcessLinesAreMarkedProcessAndGiveTheInstance(t *testing.T) { var out bytes.Buffer - requestlog.NewProcessLogger(&out, "fsn1app1/gitea").Info("starting", "version", "v1") + requestlog.NewProcessLogger(&out, "fsn1app1/gitea", slog.LevelInfo).Info("starting", + "version", "v1") var fields map[string]any @@ -94,3 +97,47 @@ func TestProcessLinesAreMarkedProcessAndGiveTheInstance(t *testing.T) { t.Errorf("process line time %q, want now in UTC with milliseconds", timeText) } } + +func TestProcessLoggerWritesTheMessagesAtItsLevelOrMoreSevere(t *testing.T) { + t.Parallel() + + levels := []slog.Level{ + slog.LevelDebug, slog.LevelInfo, slog.LevelWarn, slog.LevelError, + } + + for i, level := range levels { + t.Run(level.String(), func(t *testing.T) { + t.Parallel() + + var out bytes.Buffer + + processLog := requestlog.NewProcessLogger(&out, "fsn1app1/gitea", level) + for _, at := range levels { + processLog.Log(t.Context(), at, "message") + } + + var got, want []string + + for line := range strings.Lines(out.String()) { + var fields struct { + Level string `json:"level"` + } + + err := json.Unmarshal([]byte(line), &fields) + if err != nil { + t.Fatalf("decode %q: %v", line, err) + } + + got = append(got, fields.Level) + } + + for _, written := range levels[i:] { + want = append(want, written.String()) + } + + if !slices.Equal(got, want) { + t.Errorf("lines at %v, want %v", got, want) + } + }) + } +} diff --git a/internal/smallwebwaf/smallwebwaf.go b/internal/smallwebwaf/smallwebwaf.go index f80dddf..ab43736 100644 --- a/internal/smallwebwaf/smallwebwaf.go +++ b/internal/smallwebwaf/smallwebwaf.go @@ -70,8 +70,10 @@ func Main(version string) int { // state files, then serves requests until ctx is done. It returns the // process's exit status, 1 when smallwebwaf cannot start. func Run(ctx context.Context, params Params) int { + // Until the settings are read, the one message is an invalid setting's + // error, which every SWWAF_LOG_LEVEL lets through. processLog := requestlog.NewProcessLogger(params.Stdout, - config.InstanceName(params.LookupEnv)) + config.InstanceName(params.LookupEnv), slog.LevelError) cfg, err := config.FromEnvironment(params.LookupEnv) if err != nil { @@ -89,8 +91,11 @@ func Run(ctx context.Context, params Params) int { if cfg.LogRemoteURL != nil { remote = newRemoteLogSender(cfg) stdout = io.MultiWriter(params.Stdout, remote) - processLog = requestlog.NewProcessLogger(stdout, cfg.InstanceName) + } + processLog = requestlog.NewProcessLogger(stdout, cfg.InstanceName, cfg.LogLevel) + + if remote != nil { stopSending := startSending(ctx, remote, processLog) defer stopSending() } diff --git a/internal/smallwebwaf/smallwebwaf_test.go b/internal/smallwebwaf/smallwebwaf_test.go index 3af0fdd..b6db973 100644 --- a/internal/smallwebwaf/smallwebwaf_test.go +++ b/internal/smallwebwaf/smallwebwaf_test.go @@ -249,6 +249,54 @@ func TestServesUntilToldToStop(t *testing.T) { out.line(t, "msg", "stopped") } +func TestLogLevelHoldsBackTheLessSevereProcessLines(t *testing.T) { + t.Parallel() + + // A list that cannot be fetched has a warning written once smallwebwaf + // serves, after its starting line. + lists := httptest.NewServer(http.HandlerFunc( + func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusServiceUnavailable) + })) + t.Cleanup(lists.Close) + + ctx, stop := context.WithCancel(t.Context()) + out := &output{} + exited := make(chan int, 1) + + go func() { + exited <- run(ctx, map[string]string{ + listenAddr: localhost + ":0", + stateDir: t.TempDir(), + rulesDir: t.TempDir(), + "SWWAF_BLOCKLIST_URLS": lists.URL + "/tor.txt", + "SWWAF_LOG_LEVEL": "warn", + }, out) + }() + + out.line(t, "msg", "fetching a list failed") + stop() + + select { + case status := <-exited: + if status != 0 { + t.Fatalf("exit status %d, want 0; output:\n%s", status, out.text()) + } + case <-time.After(waitLimit): + t.Fatal("still running after being told to stop") + } + + // Not one of the info lines from the start to the stop. + for line := range strings.Lines(out.text()) { + var fields map[string]any + + err := json.Unmarshal([]byte(line), &fields) + if err != nil || fields["level"] == "INFO" { + t.Errorf("line %q (%v), want none at info", line, err) + } + } +} + func TestEveryLogLineAndMetricCarriesTheInstanceName(t *testing.T) { t.Parallel() diff --git a/internal/state/state_test.go b/internal/state/state_test.go index 7aef2c9..fe228ba 100644 --- a/internal/state/state_test.go +++ b/internal/state/state_test.go @@ -1679,7 +1679,7 @@ func newParams(dir string) state.Params { AttackBanDuration: 7 * 24 * time.Hour, MaxBans: 5000, }), - Limiter: ratelimit.New(ratelimit.Limits{}), + Limiter: ratelimit.New(ratelimit.Limits{}, 20000), GeoJS: lookup.New(lookup.Params{ Now: midnight, ProcessLog: discard, Metrics: m, }),