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, }),