diff --git a/README.md b/README.md index 7544ef9..d09e8b6 100644 --- a/README.md +++ b/README.md @@ -13,23 +13,24 @@ JSON log line for every request. Status: the first two milestones are built (https://git.eeqj.de/sneak/smallwebwaf/issues/13 and -https://git.eeqj.de/sneak/smallwebwaf/issues/14), and so are six parts of +https://git.eeqj.de/sneak/smallwebwaf/issues/14), and so are seven parts of milestone 3: the static lists, the bans that broken rate limits lead to and the JSON state files with your edits taken in while it runs, which come next in the -build order, `observe` mode, which comes a little later, and the metrics -endpoint and the header size and the idle time as settings, which come last in -it. `smallwebwaf` passes each request to the app and the app's answer back, -unchanged, within its timeouts and size limits, works out each client's address, -bans a client that sends too many requests, refuses a client that comes from a -country you refuse or from a network you refuse, lets the networks you choose -through, keeps its bans, each client's counters and history, and GeoJS's answers -in JSON files across restarts, takes in your edits of those files while it runs, -writes a JSON log line for every request, serves Prometheus metrics to a scraper -that holds the metrics token, and in `observe` mode passes on the requests it -would refuse, logging what it would have done with them. It comes as the image -the app's own image is built on. The rest of the design comes after that, in the -order of the build order in [`SPEC.md`](SPEC.md). The survey of existing tools -that led to the design is in [`EVALUATION.md`](EVALUATION.md). +build order, `observe` mode and the rest of the request log's fields, which come +a little later, and the metrics endpoint and the header size and the idle time +as settings, which come last in it. `smallwebwaf` passes each request to the app +and the app's answer back, unchanged, within its timeouts and size limits, works +out each client's address, bans a client that sends too many requests, refuses a +client that comes from a country you refuse or from a network you refuse, lets +the networks you choose through, keeps its bans, each client's counters and +history, and GeoJS's answers in JSON files across restarts, takes in your edits +of those files while it runs, writes a JSON log line for every request, serves +Prometheus metrics to a scraper that holds the metrics token, and in `observe` +mode passes on the requests it would refuse, logging what it would have done +with them. It comes as the image the app's own image is built on. The rest of +the design comes after that, in the order of the build order in +[`SPEC.md`](SPEC.md). The survey of existing tools that led to the design is in +[`EVALUATION.md`](EVALUATION.md). ## Getting started @@ -66,7 +67,9 @@ in `bin/state` unless `SWWAF_STATE_DIR` is set. address outside `SWWAF_TRUSTED_PROXIES` is the client; if every address in it is inside, the leftmost is, and with no header the peer is. The app sees what it would see from traefik directly: the same `Host`, the same - `X-Forwarded-Proto`, and `X-Forwarded-For` with the peer added at the end. + `X-Forwarded-Proto`, and `X-Forwarded-For` with the peer added at the end. It + also gets the request's id in `X-Request-ID`, the same id as in the request's + log line (see `request_id` in "Request log" below). - Enforces the timeouts and the size limits below. A limit passed before the response has started gets `smallwebwaf`'s own answer: `408` for a client too slow to send its request, `413` for a request body that is too large, `504` @@ -154,6 +157,11 @@ it, and the effective settings are logged at start. - `SWWAF_LISTEN_ADDR` (default `:8080`): where `smallwebwaf` listens. - `SWWAF_UPSTREAM_URL` (default `http://127.0.0.1:8081`): the app, as `http` or `https`, a host and an optional port, and nothing more. +- `SWWAF_INSTANCE_NAME` (default: the host's name, which docker sets to the + first 12 characters of the container's id unless the deployment names one): + the name each request log line gives as `instance`. Set it, for example to + `fsn1app1/gitea`, for a name that stays the same when a deploy replaces the + container, and that tells instances apart when several log to one place. - `SWWAF_MODE` (default `enforce`): `enforce`, or `observe` to pass on the requests `smallwebwaf` would refuse and log what it would have done (see "What it does so far" above). @@ -221,6 +229,13 @@ it, and the effective settings are logged at start. `bans.json` is written, with every ban made in between. - `SWWAF_STATE_COUNTER_INTERVAL` (default `15m`): how often every state file is written. +- `SWWAF_LOG_REQUEST_HEADERS` (default + `accept,accept-language,accept-encoding,content-type,origin,range`): the + request headers whose values the request log gives, in either case. + `Authorization`, `Cookie` and `Set-Cookie` are never logged, even when listed + (see "Request log" below). An entry naming `Host` or `Transfer-Encoding` stops + the start, since Go's HTTP server takes both out of the request; the request's + host is the field `host`. - `SWWAF_METRICS_TOKEN` (default unset): the token a scraper sends for the metrics, a long random value. While it is unset the metrics are off; one shorter than 32 characters stops the start. The settings logged at start show @@ -250,18 +265,42 @@ GeoJS are kept, for 7 days each. refused ones included: ``` -{"type":"request","time":"2026-10-03T12:00:00.123Z","client_ip":"203.0.113.9","peer_ip":"172.18.0.2","country":"DE","method":"GET","host":"app.example","path":"/","query":"","protocol":"HTTP/1.1","status":200,"upstream_status":200,"request_bytes":0,"response_bytes":5120,"referer":"","user_agent":"curl/8.9.1","action":"forward","duration_total":3.217,"duration_upstream_total":3.104} +{"type":"request","time":"2026-10-03T12:00:00.123Z","instance":"fsn1app1/gitea","client_ip":"203.0.113.9","method":"GET","scheme":"https","host":"app.example","path":"/","query":"","protocol":"HTTP/1.1","status":200,"request_bytes":0,"response_bytes":5120,"referer":"","user_agent":"curl/8.9.1","request_id":"7Q2NHZ4KJ3VXW5YB6R3MEFTD2A","peer_ip":"172.18.0.2","forwarded_for":"203.0.113.9","client_group":"203.0.113.9/32","country":"DE","request_headers":{"accept":"*/*"},"response_content_type":"text/html; charset=utf-8","upstream_status":200,"action":"forward","counts":{"minute":1,"hour":12,"day":40},"duration_total":3.217,"duration_checks":0.041,"duration_upstream_connect":0.052,"duration_upstream_first_byte":2.874,"duration_upstream_total":3.104} ``` -- `time` is when the request arrived, in UTC. `peer_ip` is the TCP peer, - normally traefik. `path` and `query` are as the client sent them. +A field that does not apply to a request is left out of its line, apart from +`type`, the fields from `time` to `user_agent`, `request_id`, `peer_ip`, +`client_group`, `country`, `action` and `duration_total`, which every line has. + +- `time` is when the request arrived, in UTC. `instance` is + `SWWAF_INSTANCE_NAME`. `scheme` is the `X-Forwarded-Proto` a trusted proxy + sent, and otherwise `http`. `path` and `query` are as the client sent them. +- `request_id` is the `X-Request-ID` a trusted proxy sent, or a new random one + of 26 letters and digits when it sent none, or when the peer is not a trusted + proxy. A request passed to the app takes it there in `X-Request-ID`. +- `peer_ip` is the TCP peer, normally traefik. `forwarded_for` is the + `X-Forwarded-For` header as received, several lines of it joined with `, `. + `client_group` is the client as the rate limits count it: its IPv4 address as + a /32, or the /64 of its IPv6 address. - `country` is the client's country as GeoJS places it. It is empty with neither country list set, for a client in `SWWAF_ALLOW_NETS` or `SWWAF_DENY_NETS`, for a client on a private, loopback or link-local address, when GeoJS cannot place the client or has not answered in time, and for a request whose client a ban covers, even when the client's country is known. +- `content_type` is the request's `Content-Type`, and `content_length` the + length the request announced for its body, which is left out for none or zero. +- `request_headers` are the request's headers that `SWWAF_LOG_REQUEST_HEADERS` + names, by name in lower case, several lines of one joined with `, `. + `Authorization`, `Cookie` and `Set-Cookie` are never among them, whatever the + setting says: `has_authorization` and `has_cookie` are there instead, and + true, when the request has an `Authorization` or a `Cookie` header. +- `websocket` is there, and true, when the app switched the connection to + another protocol, as it does for a WebSocket. - `status` is what the client was sent, `0` if nothing was; `upstream_status` is what the app answered, and is left out when the app did not answer. +- `response_content_type`, `cache_control` and `location` are the + `Content-Type`, `Cache-Control` and `Location` headers of the answer: the + app's, as passed on, or those of `smallwebwaf`'s own answer. - `request_bytes` and `response_bytes` count body bytes. - `action` is `forward` for a request passed to the app, `denied` for one refused because its client is in `SWWAF_DENY_NETS`, `banned` for one refused @@ -277,6 +316,15 @@ refused ones included: `banned`, `country_denied` or `rate_limited`. `action` then names what was done: `forward` for a request passed to the app, and another action, such as `too_large`, for one a size or time limit refused. +- `counts` gives the client's requests in the minute, the hour and the day as + the rate limits count them, this request included: in each window, those in + the bucket under way and a share of those in the bucket before, so a count can + have a fraction. For a request that broke a limit, they are the counts that + broke it. It is left out for a request the rate limits do not count: the + health check, one from a client in `SWWAF_ALLOW_NETS` or + `SWWAF_RATE_LIMIT_EXEMPT_NETS`, and one that `SWWAF_DENY_NETS`, a ban or the + country lists refuse, or would refuse in `observe` mode. The byte totals come + with the byte limits. - `limit_hit` is there for a request that broke a rate limit, and names the window whose limit it went over: `minute`, `hour` or `day`, the shortest if it went over several. `offence` is then `limit`. @@ -284,10 +332,19 @@ refused ones included: or in `observe` mode would have been refused under one, and gives when the ban ends, in the same form as `time`, or `permanent`. - `aborted` is there, and true, when the client went away early. -- `duration_total` and `duration_upstream_total` are in milliseconds. +- The timings are in milliseconds, to the microsecond. `duration_total` runs + from when the request's headers had been read to when its line is written, and + `duration_checks` over the same start to when the checks were done; the health + check runs none, and its line has no `duration_checks`. + `duration_upstream_connect`, `duration_upstream_first_byte` and + `duration_upstream_total` are there for a request passed to the app, and run + from when it was handed to the app: until there was a connection to it, new or + kept open from an earlier request, until the first byte of its answer arrived, + and until the end. The first two are left out when that never happened, as for + an app that cannot be reached. -No body and no other header is logged. `smallwebwaf`'s own messages (start, the -settings, stop, errors) share the stream as JSON lines marked +No body is logged, and no header but those above. `smallwebwaf`'s own messages +(start, the settings, stop, errors) share the stream as JSON lines marked `"type":"process"`. Go's HTTP server, on which `smallwebwaf` is built, reads a request's line and @@ -773,9 +830,8 @@ so that they run in minimal containers. ## TODO -- The rest of milestone 3: exemptions and the rest of the request log's fields; - then the rest of the design, in the order of the build order in - [`SPEC.md`](SPEC.md). +- The rest of milestone 3: exemptions; then the rest of the design, in the order + of the build order in [`SPEC.md`](SPEC.md). ## Documents diff --git a/internal/config/config.go b/internal/config/config.go index 9a63fa5..1c62687 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -12,6 +12,7 @@ import ( "net/http" "net/netip" "net/url" + "os" "path/filepath" "slices" "strconv" @@ -27,6 +28,10 @@ type Config struct { ListenAddr string // UpstreamURL is the app (SWWAF_UPSTREAM_URL). UpstreamURL *url.URL + // InstanceName is the name each request log line gives as instance + // (SWWAF_INSTANCE_NAME), by default the host's name, which docker sets + // to the first 12 characters of the container's id. + InstanceName string // Observe is true in observe mode, when SWWAF_MODE is observe rather // than enforce: a request that SWWAF_DENY_NETS, a ban, the country // lists or a rate limit would refuse is passed to the app instead, and @@ -109,6 +114,9 @@ type Config struct { StateDir string StateWriteDelay time.Duration StateCounterInterval time.Duration + // LogRequestHeaders are the request headers whose values the request + // log gives, in lower case (SWWAF_LOG_REQUEST_HEADERS). + LogRequestHeaders []string // MetricsToken is the bearer token a scraper sends for the metrics // (SWWAF_METRICS_TOKEN), "" while it is unset and the metrics are off. // MetricsTopN is how many countries get series of their own in the @@ -155,6 +163,11 @@ var ( "such as http://127.0.0.1:8081") errNotCountry = errors.New( "is not a two-letter country code such as de or kp") + errNotHeaderName = errors.New( + "is not a header name such as accept-language") + errHeaderTakenOut = errors.New( + "is taken out of every request by Go's HTTP server, so it can never " + + "be logged") errOnBothLists = errors.New("is in SWWAF_DENIED_COUNTRIES too") errNotOver4K = errors.New("is not a size of more than 4K, such as 32K") errNotDurationAboveZero = errors.New( @@ -175,9 +188,11 @@ var ( // that is set but invalid is an error that names it. func FromEnvironment(lookupEnv func(string) (string, bool)) (*Config, error) { env := &environment{lookupEnv: lookupEnv} + hostname, _ := os.Hostname() // "" when the host has no name to give cfg := &Config{ ListenAddr: env.address("SWWAF_LISTEN_ADDR", ":8080"), UpstreamURL: env.appURL("SWWAF_UPSTREAM_URL", "http://127.0.0.1:8081"), + InstanceName: env.value("SWWAF_INSTANCE_NAME", hostname), Observe: env.observe("SWWAF_MODE", "enforce"), TrustedProxies: env.netblocks("SWWAF_TRUSTED_PROXIES", privateRanges), ClientRequestTimeout: env.duration("SWWAF_CLIENT_REQUEST_TIMEOUT", "60s"), @@ -207,8 +222,10 @@ func FromEnvironment(lookupEnv func(string) (string, bool)) (*Config, error) { StateDir: env.absolutePath("SWWAF_STATE_DIR", "/var/lib/smallwebwaf"), StateWriteDelay: env.durationNotOff("SWWAF_STATE_WRITE_DELAY", "10s"), StateCounterInterval: env.durationNotOff("SWWAF_STATE_COUNTER_INTERVAL", "15m"), - MetricsToken: env.token("SWWAF_METRICS_TOKEN"), - MetricsTopN: env.numberNotOff("SWWAF_METRICS_TOP_N", "50"), + LogRequestHeaders: env.headerNames("SWWAF_LOG_REQUEST_HEADERS", + "accept,accept-language,accept-encoding,content-type,origin,range"), + MetricsToken: env.token("SWWAF_METRICS_TOKEN"), + MetricsTopN: env.numberNotOff("SWWAF_METRICS_TOP_N", "50"), } for _, country := range cfg.ExclusivelyAllowedCountries { @@ -341,6 +358,15 @@ func (e *environment) countries(name, defaultValue string) []string { return countries } +// headerNames reads a setting that is a list of header names, and +// returns them in lower case. +func (e *environment) headerNames(name, defaultValue string) []string { + headers, err := parseHeaderNames(e.value(name, defaultValue)) + e.check(name, err) + + return headers +} + // durationNotOff reads a setting that is a duration and, unlike a // timeout, cannot be off. func (e *environment) durationNotOff(name, defaultValue string) time.Duration { @@ -667,6 +693,44 @@ func parseCountries(value string) ([]string, error) { return countries, nil } +// headerNameChars are the characters RFC 9110 allows in a header name: +// letters, digits and these marks. +const headerNameChars = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz" + + "0123456789!#$%&'*+-.^_`|~" + +// parseHeaderNames reads a comma-separated list of header names in either +// case, and returns them in lower case. Host and Transfer-Encoding are +// refused: Go's HTTP server takes them out of the request's headers. +func parseHeaderNames(value string) ([]string, error) { + items, err := parseList(value) + if err != nil { + return nil, err + } + + headers := make([]string, 0, len(items)) + + for _, item := range items { + for _, char := range item { + if !strings.ContainsRune(headerNameChars, char) { + return nil, fmt.Errorf("%q %w", item, errNotHeaderName) + } + } + + header := strings.ToLower(item) + switch header { + case "host": + return nil, fmt.Errorf("%q %w; the request's host is the field host", + item, errHeaderTakenOut) + case "transfer-encoding": + return nil, fmt.Errorf("%q %w", item, errHeaderTakenOut) + } + + headers = append(headers, header) + } + + return headers, nil +} + // parseListenAddr checks an address to listen on: an optional host and a // port number. func parseListenAddr(value string) (string, error) { diff --git a/internal/config/config_test.go b/internal/config/config_test.go index 100229c..ccfe4c7 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -6,6 +6,7 @@ import ( "log/slog" "maps" "net/netip" + "os" "slices" "strings" "testing" @@ -47,8 +48,14 @@ const ( stateCounterInterval = "SWWAF_STATE_COUNTER_INTERVAL" metricsToken = "SWWAF_METRICS_TOKEN" //nolint:gosec // the setting's name metricsTopN = "SWWAF_METRICS_TOP_N" + instanceName = "SWWAF_INSTANCE_NAME" + logRequestHeaders = "SWWAF_LOG_REQUEST_HEADERS" ) +// defaultLogRequestHeaders is the default of SWWAF_LOG_REQUEST_HEADERS. +const defaultLogRequestHeaders = "accept,accept-language,accept-encoding," + + "content-type,origin,range" + // token is a token of 32 characters, the shortest allowed. const token = "0123456789abcdef0123456789abcdef" @@ -120,6 +127,18 @@ func TestDefaults(t *testing.T) { wantNetblocks(t, cfg.DenyNets) wantCountries(t, deniedCountries, cfg.DeniedCountries) wantCountries(t, allowedCountries, cfg.ExclusivelyAllowedCountries) + + hostname, err := os.Hostname() + if err != nil || hostname == "" || cfg.InstanceName != hostname { + t.Errorf("%s is %q, want the host's name %q (%v)", instanceName, + cfg.InstanceName, hostname, err) + } + + wantHeaders := strings.Split(defaultLogRequestHeaders, ",") + if !slices.Equal(cfg.LogRequestHeaders, wantHeaders) { + t.Errorf("%s gave %v, want %v", logRequestHeaders, cfg.LogRequestHeaders, + wantHeaders) + } } func TestValuesAsSet(t *testing.T) { @@ -198,6 +217,21 @@ func TestValuesAsSet(t *testing.T) { wantCountries(t, allowedCountries, cfg.ExclusivelyAllowedCountries, "DE") } +func TestInstanceNameAndLoggedHeadersAsSet(t *testing.T) { + t.Parallel() + + cfg := fromEnvironment(t, environment{ + instanceName: "fsn1app1/gitea", + logRequestHeaders: " Accept , X-Custom", + }) + + if cfg.InstanceName != "fsn1app1/gitea" || + !slices.Equal(cfg.LogRequestHeaders, []string{"accept", "x-custom"}) { + t.Errorf("%s is %q and %s gives %v", instanceName, cfg.InstanceName, + logRequestHeaders, cfg.LogRequestHeaders) + } +} + func TestCodeOnBothCountryListsStopsTheStart(t *testing.T) { t.Parallel() @@ -299,9 +333,7 @@ func TestInvalidValueStopsTheStart(t *testing.T) { t.Parallel() for _, tc := range []struct{ name, value string }{ - {listenAddr, "8080"}, - {listenAddr, ":http"}, - {listenAddr, ":65536"}, + {listenAddr, "8080"}, {listenAddr, ":http"}, {listenAddr, ":65536"}, {upstreamURL, "127.0.0.1:8081"}, {upstreamURL, "ftp://127.0.0.1:8081"}, {upstreamURL, "http://"}, @@ -319,8 +351,7 @@ func TestInvalidValueStopsTheStart(t *testing.T) { {allowNets, "192.0.2.0/24,monitoring"}, {rateLimitExemptNets, "2001:db8::/129"}, {denyNets, "198.51.100.0/24,"}, - {clientRequestTimeout, "60"}, - {clientRequestTimeout, ""}, + {clientRequestTimeout, "60"}, {clientRequestTimeout, ""}, {clientIdleTimeout, "0s"}, {clientIdleTimeout, "2 minutes"}, {clientResponseTimeout, "1y"}, @@ -361,6 +392,10 @@ func TestInvalidValueStopsTheStart(t *testing.T) { {stateWriteDelay, off}, {stateWriteDelay, "0s"}, {stateCounterInterval, off}, {stateCounterInterval, "15"}, {metricsTopN, off}, {metricsTopN, "0"}, {metricsTopN, "-1"}, + {logRequestHeaders, "accept,,origin"}, {logRequestHeaders, "accept;origin"}, + {logRequestHeaders, "accept language"}, {logRequestHeaders, "x-foo:"}, + {logRequestHeaders, "host"}, {logRequestHeaders, "accept,Host"}, + {logRequestHeaders, "transfer-encoding"}, {logRequestHeaders, "TRANSFER-ENCODING"}, } { t.Run(tc.name+"="+tc.value, func(t *testing.T) { t.Parallel() @@ -377,6 +412,27 @@ func TestInvalidValueStopsTheStart(t *testing.T) { } } +func TestHostOrTransferEncodingStopsTheStart(t *testing.T) { + t.Parallel() + + // Only Host's message points to the field host. + for value, want := range map[string]string{ + "Host": `"Host" is taken out of every request by Go's HTTP server, ` + + "so it can never be logged; the request's host is the field host", + "transfer-encoding": `"transfer-encoding" is taken out of every ` + + "request by Go's HTTP server, so it can never be logged", + } { + t.Run(value, func(t *testing.T) { + t.Parallel() + + _, err := config.FromEnvironment(environment{logRequestHeaders: value}.lookupEnv) + if err == nil || err.Error() != logRequestHeaders+": "+want { + t.Errorf("error %v, want %s: %s", err, logRequestHeaders, want) + } + }) + } +} + func TestShortTokenStopsTheStartWithoutShowingIt(t *testing.T) { t.Parallel() @@ -428,6 +484,8 @@ func TestLogsEachSettingWithItsValue(t *testing.T) { t.Fatalf("decode %s: %v", out.Bytes(), err) } + hostname, _ := os.Hostname() + want := map[string]string{ listenAddr: ":8080", upstreamURL: "http://127.0.0.1:8081", @@ -460,6 +518,8 @@ func TestLogsEachSettingWithItsValue(t *testing.T) { stateCounterInterval: "15m", metricsToken: "", metricsTopN: "50", + instanceName: hostname, + logRequestHeaders: defaultLogRequestHeaders, } if !maps.Equal(line.Settings, want) { t.Errorf("logged settings\n%v\nwant\n%v", line.Settings, want) diff --git a/internal/proxy/bans.go b/internal/proxy/bans.go index df8de16..96abb66 100644 --- a/internal/proxy/bans.go +++ b/internal/proxy/bans.go @@ -30,14 +30,17 @@ func (rq *request) banned(now time.Time) bool { return banned } -// limitBroken counts the request for the rate limits at now, and reports -// whether it takes the client over one. In enforce mode such a request -// bans the client's netblock, and sets the client's counters back to -// zero; in observe mode it does neither. +// limitBroken counts the request for the rate limits at now, notes the +// client's counts for the log line, and reports whether the request takes +// the client over a limit. In enforce mode such a request bans the +// client's netblock, and sets the client's counters back to zero; in +// observe mode it does neither. func (rq *request) limitBroken(now time.Time) bool { group := clientGroup(rq.client) - hit, over := rq.h.limiter.Count(group, now) + counts, hit, over := rq.h.limiter.Count(group, now) + rq.line.Counts = counts + if !over { return false } diff --git a/internal/proxy/client.go b/internal/proxy/client.go index e1c751e..11058b9 100644 --- a/internal/proxy/client.go +++ b/internal/proxy/client.go @@ -1,6 +1,7 @@ package proxy import ( + "crypto/rand" "net/http" "net/netip" "slices" @@ -48,6 +49,33 @@ func clientAddress( return client } +// requestIDHeader carries the request's id, from traefik and to the app. +const requestIDHeader = "X-Request-ID" + +// requestID is the request's id: the one a trusted proxy sent, or a new +// random one. A peer outside the trusted proxies did not come through +// traefik, so the id it sends is its own claim, and is replaced. +func requestID(r *http.Request, peerTrusted bool) string { + id := r.Header.Get(requestIDHeader) + if !peerTrusted || id == "" { + id = rand.Text() + } + + return id +} + +// scheme is how the client reached traefik, as a trusted proxy says in +// X-Forwarded-Proto, or otherwise http, the only scheme smallwebwaf +// serves. +func scheme(r *http.Request, peerTrusted bool) string { + proto := r.Header.Get("X-Forwarded-Proto") + if !peerTrusted || proto == "" { + return "http" + } + + return proto +} + // ipv6GroupPrefix is the length of the IPv6 netblock that is one client. const ipv6GroupPrefix = 64 diff --git a/internal/proxy/client_test.go b/internal/proxy/client_test.go index 37b4951..cf4ece5 100644 --- a/internal/proxy/client_test.go +++ b/internal/proxy/client_test.go @@ -14,10 +14,14 @@ const ( appHost = "app.example" // client is the client's address, as a proxy names it. client = "203.0.113.9" - // forwardedFor is the header that lists the client and its proxies. - forwardedFor = "X-Forwarded-For" - // secure is the scheme a client reached traefik with. + // forwardedFor is the header that lists the client and its proxies, + // and forwardedProto the one that gives the scheme the client used. + forwardedFor = "X-Forwarded-For" + forwardedProto = "X-Forwarded-Proto" + // secure is the scheme a client reached traefik with, and plain the + // one smallwebwaf serves. secure = "https" + plain = "http" ) // appHeaders is what the app tells about the headers it received. @@ -65,13 +69,13 @@ func TestClientAddressAndForwardedHeaders(t *testing.T) { func clientAddressCases() []clientAddressCase { trusted := map[string]string{trustedProxies: trustLocalhost} forged := http.Header{ - forwardedFor: {client}, - "X-Forwarded-Host": {"forged.example"}, - "X-Forwarded-Proto": {secure}, - "X-Real-Ip": {client}, + forwardedFor: {client}, + "X-Forwarded-Host": {"forged.example"}, + forwardedProto: {secure}, + "X-Real-Ip": {client}, } replaced := appHeaders{ - ForwardedFor: localhost, ForwardedHost: appHost, ForwardedProto: "http", + ForwardedFor: localhost, ForwardedHost: appHost, ForwardedProto: plain, } return []clientAddressCase{{ @@ -87,10 +91,10 @@ func clientAddressCases() []clientAddressCase { "outside the trusted proxies from the right", env: trusted, header: http.Header{ - forwardedFor: {"198.51.100.7, " + client + ", 10.0.0.2"}, - "X-Forwarded-Host": {appHost}, - "X-Forwarded-Proto": {secure}, - "X-Real-Ip": {client}, + forwardedFor: {"198.51.100.7, " + client + ", 10.0.0.2"}, + "X-Forwarded-Host": {appHost}, + forwardedProto: {secure}, + "X-Real-Ip": {client}, }, wantClient: client, wantApp: appHeaders{ @@ -138,7 +142,7 @@ func requestWithHeaders( Host: r.Host, ForwardedFor: r.Header.Get(forwardedFor), ForwardedHost: r.Header.Get("X-Forwarded-Host"), - ForwardedProto: r.Header.Get("X-Forwarded-Proto"), + ForwardedProto: r.Header.Get(forwardedProto), RealIP: r.Header.Get("X-Real-IP"), }) }) diff --git a/internal/proxy/health_test.go b/internal/proxy/health_test.go index eacf49e..e069d98 100644 --- a/internal/proxy/health_test.go +++ b/internal/proxy/health_test.go @@ -21,14 +21,18 @@ func TestHealthEndpointIsAnsweredBeforeAnyCheck(t *testing.T) { // the last one would have it refused. addr, out := startProxy(t, app.URL, map[string]string{rateLimitPerMinute: "1"}) - const healthChecks = 3 + const ( + healthChecks = 3 + contentType = "text/plain; charset=utf-8" + ) for range healthChecks { got := get(t, addr, proxy.HealthPath) wantStatus(t, got, http.StatusOK) - if string(got.body) != "ok\n" { - t.Errorf("health endpoint answered %q, want ok", got.body) + if string(got.body) != "ok\n" || got.header.Get("Content-Type") != contentType { + t.Errorf("health endpoint answered %q with Content-Type %q, want ok "+ + "with %q", got.body, got.header.Get("Content-Type"), contentType) } } @@ -37,6 +41,11 @@ func TestHealthEndpointIsAnsweredBeforeAnyCheck(t *testing.T) { lines := out.requestLines(t, healthChecks+1) for _, line := range lines[:healthChecks] { wantLine(t, line, http.StatusOK, requestlog.ActionAdmin) + + if line.ResponseContentType != contentType { + t.Errorf("health check's log line has response_content_type %q, "+ + "want %q", line.ResponseContentType, contentType) + } } wantLine(t, lines[healthChecks], http.StatusOK, requestlog.ActionForward) diff --git a/internal/proxy/passthrough_test.go b/internal/proxy/passthrough_test.go index c8a6ad6..5a7f015 100644 --- a/internal/proxy/passthrough_test.go +++ b/internal/proxy/passthrough_test.go @@ -6,6 +6,8 @@ import ( "errors" "io" "net/http" + "os" + "reflect" "slices" "strings" "sync/atomic" @@ -14,6 +16,7 @@ import ( "sneak.berlin/go/smallwebwaf/internal/config" "sneak.berlin/go/smallwebwaf/internal/proxy" + "sneak.berlin/go/smallwebwaf/internal/ratelimit" "sneak.berlin/go/smallwebwaf/internal/requestlog" ) @@ -115,27 +118,34 @@ func wantAnswer(t *testing.T, got answer, body []byte) { } } -// wantRequestFields checks the log line's fields about the request. +// wantRequestFields checks the log line's fields about the request. Its +// time, its id and its timings are checked only for being there. func wantRequestFields(t *testing.T, line logLine, host string, sent, received int) { t.Helper() - want := requestlog.Line{ - Type: "request", Time: line.Time, ClientIP: localhost, PeerIP: localhost, - Method: http.MethodPatch, Host: host, Path: rawPath, Query: rawQuery, - Protocol: "HTTP/1.1", Status: http.StatusTeapot, - UpstreamStatus: http.StatusTeapot, RequestBytes: int64(sent), + hostname, _ := os.Hostname() + + want := withTimings(line, requestlog.Line{ + Type: requestType, Time: line.Time, Instance: hostname, + ClientIP: localhost, Method: http.MethodPatch, Scheme: plain, Host: host, + Path: rawPath, Query: rawQuery, Protocol: protocol, + Status: http.StatusTeapot, RequestBytes: int64(sent), ResponseBytes: int64(received), UserAgent: "test-agent", - Action: requestlog.ActionForward, DurationTotal: line.DurationTotal, - DurationUpstreamTotal: line.DurationUpstreamTotal, - } - if line.Line != want { + RequestID: line.RequestID, PeerIP: localhost, ClientGroup: localhost + "/32", + ContentLength: int64(sent), ResponseContentType: "text/plain; charset=utf-8", + UpstreamStatus: http.StatusTeapot, Action: requestlog.ActionForward, + Counts: ratelimit.Counts{Minute: 1, Hour: 1, Day: 1}, + }) + if !reflect.DeepEqual(line.Line, want) { t.Errorf("log line\n%+v\nwant\n%+v", line.Line, want) } _, err := time.Parse(time.RFC3339, line.Time) - if err != nil || line.DurationTotal <= 0 || line.DurationUpstreamTotal <= 0 { - t.Errorf("log line has time %q and durations %v and %v", - line.Time, line.DurationTotal, line.DurationUpstreamTotal) + if err != nil || line.RequestID == "" || line.DurationTotal <= 0 || + line.DurationUpstreamTotal == nil || *line.DurationUpstreamTotal <= 0 { + t.Errorf("log line has time %q, request_id %q and durations %v and %v", + line.Time, line.RequestID, line.DurationTotal, + line.fields["duration_upstream_total"]) } } @@ -371,8 +381,13 @@ func TestAnswers502WhenTheAppCannotBeReached(t *testing.T) { addr, out := startProxy(t, "http://"+localhost+":1", nil) wantStatus(t, get(t, addr, "/"), http.StatusBadGateway) - wantLine(t, out.requestLine(t), http.StatusBadGateway, - requestlog.ActionUpstreamError) + + line := out.requestLine(t) + wantLine(t, line, http.StatusBadGateway, requestlog.ActionUpstreamError) + + // There never was a connection to the app, nor an answer from it. + wantTimings(t, line, "duration_total", "duration_checks", + "duration_upstream_total") logged := slices.ContainsFunc(out.lines(t), func(line map[string]any) bool { return line["type"] == "process" && line["msg"] == "request to the app failed" diff --git a/internal/proxy/proxy.go b/internal/proxy/proxy.go index 2c9bf13..a651f4d 100644 --- a/internal/proxy/proxy.go +++ b/internal/proxy/proxy.go @@ -160,6 +160,9 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // a health checker is never refused. It does not ask the app. if r.Method == http.MethodGet && r.URL.Path == HealthPath { rq.line.Action = requestlog.ActionAdmin + // Set here rather than left to Go's server, which would set it only + // after the log line has taken the response's headers. + rq.out.Header().Set("Content-Type", "text/plain; charset=utf-8") _, _ = io.WriteString(rq.out, "ok\n") return @@ -169,6 +172,8 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { defer rq.addToHistory() refused := rq.check(r.Context()) + rq.checked = time.Now() + if refused != nil { rq.answer(*refused) diff --git a/internal/proxy/proxy_test.go b/internal/proxy/proxy_test.go index bcff4cc..ccb3bed 100644 --- a/internal/proxy/proxy_test.go +++ b/internal/proxy/proxy_test.go @@ -35,6 +35,10 @@ const ( // localhost is where every test server listens, and so the address // smallwebwaf sees each test's requests come from. localhost = "127.0.0.1" + // requestType is the type that marks a request log line. + requestType = "request" + // protocol is the protocol of every test's requests. + protocol = "HTTP/1.1" ) // shortTimeoutSetting is shortTimeout as a setting's value. @@ -67,6 +71,8 @@ const ( maxBanDuration = "SWWAF_MAX_BAN_DURATION" maxBans = "SWWAF_MAX_BANS" banScopeV4Prefix = "SWWAF_BAN_SCOPE_V4_PREFIX" + instanceName = "SWWAF_INSTANCE_NAME" + logRequestHeaders = "SWWAF_LOG_REQUEST_HEADERS" ) // output collects what smallwebwaf writes on stdout. @@ -83,6 +89,14 @@ func (o *output) Write(p []byte) (int, error) { return o.buf.Write(p) } +// text returns everything written so far. +func (o *output) text() string { + o.mu.Lock() + defer o.mu.Unlock() + + return o.buf.String() +} + // lines returns every line written so far, decoded. func (o *output) lines(t *testing.T) []map[string]any { t.Helper() @@ -122,7 +136,7 @@ func (o *output) requestLines(t *testing.T, count int) []logLine { var found []logLine for _, fields := range o.lines(t) { - if fields["type"] == "request" { + if fields["type"] == requestType { found = append(found, decodeLine(t, fields)) } } diff --git a/internal/proxy/request.go b/internal/proxy/request.go index 71d571e..09dfef1 100644 --- a/internal/proxy/request.go +++ b/internal/proxy/request.go @@ -8,6 +8,7 @@ import ( "net/http/httputil" "net/netip" "os" + "strings" "sync" "sync/atomic" "time" @@ -46,7 +47,9 @@ type request struct { peer netip.Addr peerTrusted bool start time.Time - // upstreamStart is when the request was handed to the app. + // checked is when the checks were done, and upstreamStart when the + // request was handed to the app. + checked time.Time upstreamStart time.Time // cancel ends the request to the app. cancel context.CancelFunc @@ -56,26 +59,34 @@ type request struct { complete bool // mu guards what follows. The timeouts run on goroutines of their - // own, and the transport starts and stops them from its own; once - // timersStopped is set, none of them acts any more. + // own, and the transport starts and stops them, and notes the times + // below, from its own; once timersStopped is set, none of the timeouts + // acts any more. mu sync.Mutex timersStopped bool clientRequestTimer *time.Timer upstreamRequestTimer *time.Timer upstreamResponseTimer *time.Timer - // requestSent is when the app had been sent the whole request. - requestSent time.Time + // connected is when there was a connection to the app, requestSent + // when the app had been sent the whole request, and answerStarted + // when the first byte of its answer arrived. + connected time.Time + requestSent time.Time + answerStarted time.Time } // newRequest starts handling r: it notes the time, counts the request as -// under way, and works out the client. +// under way, works out the client, and starts the log line with what is +// known of the request. func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request { h.metrics.RequestStarted() start := time.Now() peer := peerAddress(r) trusted := h.config.TrustedProxies - client := clientAddress(peer, r.Header.Values("X-Forwarded-For"), trusted) + peerTrusted := isInside(peer, trusted) + forwardedFor := r.Header.Values("X-Forwarded-For") + client := clientAddress(peer, forwardedFor, trusted) rq := &request{ h: h, @@ -84,22 +95,37 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request { out: &responseWriter{ResponseWriter: w}, client: client, peer: peer, - peerTrusted: isInside(peer, trusted), + peerTrusted: peerTrusted, start: start, line: requestlog.Line{ - Time: requestlog.FormatTime(start), - ClientIP: client.String(), - PeerIP: peer.String(), - Method: r.Method, - Host: r.Host, - Path: r.URL.EscapedPath(), - Query: r.URL.RawQuery, - Protocol: r.Proto, - Referer: r.Referer(), - UserAgent: r.UserAgent(), - Action: requestlog.ActionForward, + Time: requestlog.FormatTime(start), + Instance: h.config.InstanceName, + ClientIP: client.String(), + Method: r.Method, + Scheme: scheme(r, peerTrusted), + Host: r.Host, + Path: r.URL.EscapedPath(), + Query: r.URL.RawQuery, + Protocol: r.Proto, + Referer: r.Referer(), + UserAgent: r.UserAgent(), + RequestID: requestID(r, peerTrusted), + PeerIP: peer.String(), + ForwardedFor: strings.Join(forwardedFor, ", "), + ClientGroup: clientGroup(client).String(), + ContentType: r.Header.Get("Content-Type"), + RequestHeaders: requestHeaders(r, h.config.LogRequestHeaders), + HasAuthorization: len(r.Header.Values("Authorization")) > 0, + HasCookie: len(r.Header.Values("Cookie")) > 0, + Action: requestlog.ActionForward, }, } + + // A length of -1 is a body whose length was not announced. + if r.ContentLength > 0 { + rq.line.ContentLength = r.ContentLength + } + if r.Body != http.NoBody { rq.body = &requestBody{body: limitBody(r.Body, h.config.RequestMaxBytes), rq: rq} } @@ -107,6 +133,27 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request { return rq } +// requestHeaders returns the headers of r that names lists, by name in +// lower case, each with its values joined by ", ". Authorization, Cookie +// and Set-Cookie are never among them, whatever names says. +func requestHeaders(r *http.Request, names []string) map[string]string { + headers := map[string]string{} + + for _, name := range names { + switch name { + case "authorization", "cookie", "set-cookie": + continue + } + + values := r.Header.Values(name) + if len(values) > 0 { + headers[name] = strings.Join(values, ", ") + } + } + + return headers +} + // check is the one place where a request can be refused once its client // is known, before its body is read or anything reaches the app. It // returns nil to let the request through. The checks of checkClient come @@ -182,7 +229,9 @@ func (rq *request) forward(ctx context.Context) { rq.cancel = cancel ctx = httptrace.WithClientTrace(ctx, &httptrace.ClientTrace{ - WroteRequest: rq.wroteRequest, + GotConn: rq.gotConn, + WroteRequest: rq.wroteRequest, + GotFirstResponseByte: rq.gotFirstResponseByte, }) out := rq.in.WithContext(ctx) @@ -205,7 +254,8 @@ func (rq *request) forward(ctx context.Context) { } // rewrite makes the request the app receives: the client's request, -// unchanged, sent to SWWAF_UPSTREAM_URL, with the forwarded headers set. +// unchanged, sent to SWWAF_UPSTREAM_URL, with the forwarded headers and +// the request's id set. func (rq *request) rewrite(pr *httputil.ProxyRequest) { upstream := rq.h.config.UpstreamURL pr.Out.URL.Scheme = upstream.Scheme @@ -214,6 +264,7 @@ func (rq *request) rewrite(pr *httputil.ProxyRequest) { // the query as the client sent it. pr.Out.URL.RawQuery = pr.In.URL.RawQuery setForwardedHeaders(pr.In, pr.Out, rq.peer, rq.peerTrusted) + pr.Out.Header.Set(requestIDHeader, rq.line.RequestID) } // modifyResponse looks at the app's answer before ReverseProxy passes it @@ -227,6 +278,7 @@ func (rq *request) modifyResponse(res *http.Response) error { // connection it takes over, not through rq.out. rq.stopTimers() rq.out.status = res.StatusCode + rq.line.Websocket = true return nil } @@ -322,6 +374,10 @@ func (rq *request) finish() { line := &rq.line line.Status = rq.out.status line.ResponseBytes = rq.out.bytes + header := rq.out.Header() + line.ResponseContentType = header.Get("Content-Type") + line.CacheControl = header.Get("Cache-Control") + line.Location = header.Get("Location") if rq.body != nil { line.RequestBytes = rq.body.bytes.Load() @@ -346,12 +402,18 @@ func (rq *request) finish() { now := time.Now() duration := now.Sub(rq.start) line.DurationTotal = requestlog.Milliseconds(duration) + line.DurationChecks = timing(rq.start, rq.checked) var upstreamDuration time.Duration if !rq.upstreamStart.IsZero() { upstreamDuration = now.Sub(rq.upstreamStart) - line.DurationUpstreamTotal = requestlog.Milliseconds(upstreamDuration) + line.DurationUpstreamTotal = new(requestlog.Milliseconds(upstreamDuration)) + + rq.mu.Lock() + line.DurationUpstreamConnect = timing(rq.upstreamStart, rq.connected) + line.DurationUpstreamFirstByte = timing(rq.upstreamStart, rq.answerStarted) + rq.mu.Unlock() } // Counted before the log line is written, so that the metrics count @@ -364,6 +426,17 @@ func (rq *request) finish() { } } +// timing is the time from start to end in milliseconds, for one of the +// log line's timings, or nil when end is zero: what it times never +// happened. +func timing(start, end time.Time) *float64 { + if end.IsZero() { + return nil + } + + return new(requestlog.Milliseconds(end.Sub(start))) +} + // addToHistory adds the request, which has ended, to its client's // history. func (rq *request) addToHistory() { @@ -473,6 +546,24 @@ func (rq *request) bodyReceived() { stopTimer(rq.clientRequestTimer) } +// gotConn is called once there is a connection to the app, a new one or +// one kept open from an earlier request. +func (rq *request) gotConn(httptrace.GotConnInfo) { + rq.mu.Lock() + defer rq.mu.Unlock() + + rq.connected = time.Now() +} + +// gotFirstResponseByte is called once the first byte of the app's answer +// has arrived. +func (rq *request) gotFirstResponseByte() { + rq.mu.Lock() + defer rq.mu.Unlock() + + rq.answerStarted = time.Now() +} + // wroteRequest is called once the app has been sent the whole request: // the request timeouts end and SWWAF_UPSTREAM_RESPONSE_TIMEOUT starts. func (rq *request) wroteRequest(info httptrace.WroteRequestInfo) { diff --git a/internal/proxy/requestlog_test.go b/internal/proxy/requestlog_test.go new file mode 100644 index 0000000..98d2104 --- /dev/null +++ b/internal/proxy/requestlog_test.go @@ -0,0 +1,368 @@ +package proxy_test + +import ( + "io" + "maps" + "math" + "net/http" + "reflect" + "slices" + "strings" + "testing" + "time" + + "sneak.berlin/go/smallwebwaf/internal/proxy" + "sneak.berlin/go/smallwebwaf/internal/ratelimit" + "sneak.berlin/go/smallwebwaf/internal/requestlog" +) + +const ( + // requestIDHeader carries the request's id. + requestIDHeader = "X-Request-ID" + // instance is the SWWAF_INSTANCE_NAME a test sets. + instance = "fsn1app1/gitea" + // ipv6Client is a client on IPv6, and ipv6Group the netblock the rate + // limits count it as. + ipv6Client = "2001:db8::7" + ipv6Group = "2001:db8::/64" +) + +func TestLogLineHasEachFieldWhereItApplies(t *testing.T) { + t.Parallel() + + received := make(chan string, 2) // the request ids the app received + app := startApp(t, func(w http.ResponseWriter, r *http.Request) { + received <- r.Header.Get(requestIDHeader) + + _, _ = io.Copy(io.Discard, r.Body) + + if r.URL.Path != "/full" { + w.WriteHeader(http.StatusNoContent) + + return + } + + w.Header().Set("Content-Type", "text/html") + w.Header().Set("Cache-Control", "no-store") + w.Header().Set("Location", "/elsewhere") + w.WriteHeader(http.StatusFound) + _, _ = io.WriteString(w, "moved") + }) + addr, out := startProxy(t, app.URL, map[string]string{ + trustedProxies: trustLocalhost, + rateLimitExemptNets: localhost, + instanceName: instance, + logRequestHeaders: "Accept,x-custom,Authorization,cookie,SET-COOKIE", + }) + + // This request comes from ipv6Client through a trusted proxy, with a + // body and each header the log line looks at, and is answered with a + // redirect. + conn := dial(t, addr) + send(t, conn, "POST /full HTTP/1.1\r\nHost: "+appHost+"\r\n"+ + forwardedFor+": 198.51.100.7, "+ipv6Client+"\r\n"+ + forwardedProto+": "+secure+"\r\n"+requestIDHeader+": from-traefik\r\n"+ + "Content-Type: application/x-www-form-urlencoded\r\nContent-Length: 3\r\n"+ + "Accept: text/html\r\nX-Custom: one\r\nX-Custom: two\r\n"+ + "Authorization: Bearer secret-token\r\nCookie: session=secret-cookie\r\n"+ + "Set-Cookie: secret-set-cookie\r\n\r\na=b") + wantStatus(t, readResponse(t, conn), http.StatusFound) + + // A request's log line can come after its answer: each is waited for + // before the next request, so that the lines are in order. + full := out.requestLines(t, 1)[0] + + // This one comes from 127.0.0.1, which the rate limits do not count, + // with a body of 4 bytes whose length it does not announce, so that its + // request_bytes is not its content_length, and no header the log line + // looks at, and is answered with 204 and no header. + conn = dial(t, addr) + send(t, conn, "POST /bare HTTP/1.1\r\nHost: "+appHost+"\r\n"+ + "Transfer-Encoding: chunked\r\n\r\n4\r\nbody\r\n0\r\n\r\n") + wantStatus(t, readResponse(t, conn), http.StatusNoContent) + + bare := out.requestLines(t, 2)[1] + + wantFullLine(t, full) + wantBareLine(t, bare) + + for _, line := range []logLine{full, bare} { + got := <-received + if got != line.RequestID { + t.Errorf("the app received request id %q, the log line has %q", + got, line.RequestID) + } + } + + if strings.Contains(out.text(), "secret") { + t.Errorf("a value of Authorization, Cookie or Set-Cookie is logged:\n%s", + out.text()) + } +} + +// wantFullLine checks the log line of the request with every header the +// line looks at. Its timings are checked by TestTimingsAreInOrder. +func wantFullLine(t *testing.T, line logLine) { + t.Helper() + + headers := map[string]string{"accept": "text/html", "x-custom": "one, two"} + + want := withTimings(line, requestlog.Line{ + Type: requestType, Time: line.Time, Instance: instance, + ClientIP: ipv6Client, Method: http.MethodPost, Scheme: secure, + Host: appHost, Path: "/full", Protocol: protocol, + Status: http.StatusFound, RequestBytes: 3, ResponseBytes: 5, + RequestID: "from-traefik", PeerIP: localhost, + ForwardedFor: "198.51.100.7, " + ipv6Client, ClientGroup: ipv6Group, + ContentType: "application/x-www-form-urlencoded", ContentLength: 3, + RequestHeaders: headers, HasAuthorization: true, HasCookie: true, + ResponseContentType: "text/html", UpstreamStatus: http.StatusFound, + CacheControl: "no-store", Location: "/elsewhere", + Action: requestlog.ActionForward, + Counts: ratelimit.Counts{Minute: 1, Hour: 1, Day: 1}, + }) + if !reflect.DeepEqual(line.Line, want) { + t.Errorf("log line\n%+v\nwant\n%+v", line.Line, want) + } +} + +// wantBareLine checks the log line of the request with none of them, and +// that the fields that do not apply to it are left out. +func wantBareLine(t *testing.T, line logLine) { + t.Helper() + + want := withTimings(line, requestlog.Line{ + Type: requestType, Time: line.Time, Instance: instance, + ClientIP: localhost, Method: http.MethodPost, Scheme: plain, + Host: appHost, Path: "/bare", Protocol: protocol, + Status: http.StatusNoContent, RequestBytes: 4, RequestID: line.RequestID, + PeerIP: localhost, ClientGroup: localhost + "/32", + UpstreamStatus: http.StatusNoContent, Action: requestlog.ActionForward, + }) + if !reflect.DeepEqual(line.Line, want) || line.RequestID == "" { + t.Errorf("log line\n%+v\nwant\n%+v, with a request id", line.Line, want) + } + + for _, name := range []string{ + "forwarded_for", "content_type", "content_length", "request_headers", + "has_authorization", "has_cookie", "websocket", "response_content_type", + "cache_control", "location", "counts", + } { + _, present := line.fields[name] + if present { + t.Errorf("log line has %s, which does not apply", name) + } + } +} + +// withTimings returns want with the timings of line. +func withTimings(line logLine, want requestlog.Line) requestlog.Line { + want.DurationTotal = line.DurationTotal + want.DurationChecks = line.DurationChecks + want.DurationUpstreamConnect = line.DurationUpstreamConnect + want.DurationUpstreamFirstByte = line.DurationUpstreamFirstByte + want.DurationUpstreamTotal = line.DurationUpstreamTotal + + return want +} + +func TestHasAuthorizationAndHasCookieEachComeFromTheirOwnHeader(t *testing.T) { + t.Parallel() + + const hasAuthorization, hasCookie = "has_authorization", "has_cookie" + + for _, tc := range []struct{ header, field, other string }{ + {"Authorization", hasAuthorization, hasCookie}, + {"Cookie", hasCookie, hasAuthorization}, + } { + t.Run("only "+tc.header, func(t *testing.T) { + t.Parallel() + + app := startApp(t, func(http.ResponseWriter, *http.Request) {}) + addr, out := startProxy(t, app.URL, nil) + + req := newRequest(t, http.MethodGet, addr, "/", http.NoBody) + req.Header.Set(tc.header, "secret") + wantStatus(t, do(t, req), http.StatusOK) + + line := out.requestLine(t) + + _, otherPresent := line.fields[tc.other] + if line.fields[tc.field] != true || otherPresent { + t.Errorf("log line has %s %v and %s %v, want true and none", + tc.field, line.fields[tc.field], tc.other, line.fields[tc.other]) + } + }) + } +} + +func TestRequestIDAndSchemeComeOnlyFromATrustedProxy(t *testing.T) { + t.Parallel() + + const sentID = "from-traefik" + + sent := http.Header{requestIDHeader: {sentID}, forwardedProto: {secure}} + trusted := map[string]string{trustedProxies: trustLocalhost} + + for _, tc := range []struct { + name string + env map[string]string + header http.Header + // wantID is the request id logged, "" for a new one. + wantID, wantScheme string + }{ + {"a trusted proxy's are kept", trusted, sent, sentID, secure}, + {"without them, the id is new and the scheme http", trusted, nil, "", plain}, + {"another peer's are replaced", nil, sent, "", plain}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + received := make(chan string, 2) + app := startApp(t, func(_ http.ResponseWriter, r *http.Request) { + received <- r.Header.Get(requestIDHeader) + }) + addr, out := startProxy(t, app.URL, tc.env) + + // Two requests, so that two new ids can be told apart. + ids := make([]string, 0, 2) + + for i := range 2 { + req := newRequest(t, http.MethodGet, addr, "/", http.NoBody) + maps.Copy(req.Header, tc.header) + wantStatus(t, do(t, req), http.StatusOK) + + line := out.requestLines(t, i+1)[i] + ids = append(ids, line.RequestID) + + got := <-received + if line.RequestID != got || line.Scheme != tc.wantScheme { + t.Errorf("log line has request_id %q and scheme %q, and the "+ + "app received id %q; want the same id and scheme %q", + line.RequestID, line.Scheme, got, tc.wantScheme) + } + } + + switch { + case tc.wantID != "" && (ids[0] != tc.wantID || ids[1] != tc.wantID): + t.Errorf("request ids %q, want %q", ids, tc.wantID) + case tc.wantID == "" && (slices.Contains(ids, sentID) || + slices.Contains(ids, "") || ids[0] == ids[1]): + t.Errorf("request ids %q, want two new ones", ids) + } + }) + } +} + +func TestTimingsAreInOrder(t *testing.T) { + t.Parallel() + + const denied = "192.0.2.50" // in SWWAF_DENY_NETS + + app := startApp(t, func(w http.ResponseWriter, _ *http.Request) { + // The pauses set the times apart; a hold-up of the test only + // lengthens them. + time.Sleep(time.Millisecond) + w.WriteHeader(http.StatusOK) + _ = http.NewResponseController(w).Flush() + + time.Sleep(time.Millisecond) + + _, _ = io.WriteString(w, "done") + }) + addr, out := startProxy(t, app.URL, map[string]string{ + trustedProxies: trustLocalhost, + denyNets: denied, + }) + + // Each log line is waited for before the next request, so that the + // lines are in order. + wantStatus(t, get(t, addr, "/"), http.StatusOK) + forwarded := out.requestLines(t, 1)[0] + + req := newRequest(t, http.MethodGet, addr, "/", http.NoBody) + req.Header.Set(forwardedFor, denied) + wantStatus(t, do(t, req), http.StatusForbidden) + refused := out.requestLines(t, 2)[1] + + wantStatus(t, get(t, addr, proxy.HealthPath), http.StatusOK) + health := out.requestLines(t, 3)[2] + + // A request passed to the app has every timing; one refused, none of + // the app's; the health check, which runs no check, only the total. + wantTimings(t, forwarded, "duration_total", "duration_checks", + "duration_upstream_connect", "duration_upstream_first_byte", + "duration_upstream_total") + wantTimings(t, refused, "duration_total", "duration_checks") + wantTimings(t, health, "duration_total") + + if t.Failed() { + return + } + + // In whole microseconds, as they are logged, so that the sum below is + // exact. + total := microseconds(forwarded.DurationTotal) + checks := microseconds(*forwarded.DurationChecks) + connect := microseconds(*forwarded.DurationUpstreamConnect) + firstByte := microseconds(*forwarded.DurationUpstreamFirstByte) + upstream := microseconds(*forwarded.DurationUpstreamTotal) + + // The checks end before the request is handed to the app, and the + // connection comes before the answer, which the app ends after a + // pause. + if checks+upstream > total || connect >= firstByte || firstByte >= upstream { + t.Errorf("timings in microseconds: total %d, checks %d, connect %d, "+ + "first byte %d, upstream total %d", total, checks, connect, firstByte, + upstream) + } + + if *refused.DurationChecks > refused.DurationTotal { + t.Errorf("refused request's checks took %v of %v milliseconds", + *refused.DurationChecks, refused.DurationTotal) + } +} + +// wantTimings checks that the timings named are the only ones line has. +func wantTimings(t *testing.T, line logLine, want ...string) { + t.Helper() + + var got []string + + for name := range line.fields { + if strings.HasPrefix(name, "duration_") { + got = append(got, name) + } + } + + slices.Sort(got) + slices.Sort(want) + + if !slices.Equal(got, want) { + t.Errorf("log line of %s has timings %v, want %v", line.Path, got, want) + } +} + +// microseconds is a timing in whole microseconds. +func microseconds(milliseconds float64) int64 { + return int64(math.Round(milliseconds * 1000)) +} + +func TestLogsAnUpgradedConnection(t *testing.T) { + t.Parallel() + + app := startApp(t, echoAfterUpgrade) + addr, out := startProxy(t, app.URL, nil) + + conn := dial(t, addr) + send(t, conn, "GET /socket HTTP/1.1\r\nHost: app\r\n"+ + "Connection: Upgrade\r\nUpgrade: websocket\r\n\r\n") + wantStatus(t, readResponse(t, conn), http.StatusSwitchingProtocols) + + _ = conn.Close() + + line := out.requestLine(t) + if line.fields["websocket"] != true { + t.Errorf("log line has websocket %v, want true", line.fields["websocket"]) + } +} diff --git a/internal/ratelimit/ratelimit.go b/internal/ratelimit/ratelimit.go index fb25801..9a7b68b 100644 --- a/internal/ratelimit/ratelimit.go +++ b/internal/ratelimit/ratelimit.go @@ -149,26 +149,39 @@ type Hit struct { Requests float64 } +// Counts are a client's requests in the minute, the hour and the day that +// end at a request, that request included. +type Counts struct { + Minute float64 `json:"minute"` + Hour float64 `json:"hour"` + Day float64 `json:"day"` +} + // Count counts a request from client at now, in every window, whether or -// not it is refused. It reports whether the request takes the client over -// a limit, and the window whose limit it goes over, the shortest if it is -// over several. -func (l *Limiter) Count(client netip.Prefix, now time.Time) (Hit, bool) { +// not it is refused, and returns the client's requests in each window. It +// reports whether the request takes the client over a limit, and the +// window whose limit it goes over, the shortest if it is over several. +func (l *Limiter) Count(client netip.Prefix, now time.Time) (Counts, Hit, bool) { l.mu.Lock() defer l.mu.Unlock() - var hit Hit + var ( + requests [3]float64 + hit Hit + ) for i, b := range l.get(client).buckets() { w := l.windows[i] - requests := b.add(now, w.length) - if hit.Window == "" && w.limit > 0 && requests > float64(w.limit) { - hit = Hit{Window: w.name, Limit: w.limit, Requests: requests} + requests[i] = b.add(now, w.length) + if hit.Window == "" && w.limit > 0 && requests[i] > float64(w.limit) { + hit = Hit{Window: w.name, Limit: w.limit, Requests: requests[i]} } } - return hit, hit.Window != "" + counts := Counts{Minute: requests[0], Hour: requests[1], Day: requests[2]} + + return counts, hit, hit.Window != "" } // Reset sets client's counts in every window back to zero. Its history diff --git a/internal/ratelimit/ratelimit_test.go b/internal/ratelimit/ratelimit_test.go index 891fc3b..49bb3ec 100644 --- a/internal/ratelimit/ratelimit_test.go +++ b/internal/ratelimit/ratelimit_test.go @@ -62,14 +62,14 @@ func TestHitGivesTheLimitAndTheRequestsCounted(t *testing.T) { start := midnight() for range limit { - _, over := limiter.Count(client, start) + _, _, over := limiter.Count(client, start) if over { t.Fatal("a request within the limit is over it") } } // Over both limits; the minute's is named, with the four requests. - hit, over := limiter.Count(client, start) + _, hit, over := limiter.Count(client, start) want := ratelimit.Hit{Window: minute, Limit: limit, Requests: limit + 1} if !over || hit != want { @@ -78,6 +78,29 @@ func TestHitGivesTheLimitAndTheRequestsCounted(t *testing.T) { } } +func TestCountGivesTheRequestsInEachWindow(t *testing.T) { + t.Parallel() + + limiter := ratelimit.New(ratelimit.Limits{}) + client := netip.MustParsePrefix("203.0.113.9/32") + start := midnight() + + for range 3 { + limiter.Count(client, start) + } + + // A quarter into the next hour, the minute has only this request. The + // hour still covers three quarters of the bucket before, with its three + // requests, which count 2.25, and this one: 3.25. The day covers all + // four. + counts, _, _ := limiter.Count(client, start.Add(time.Hour+time.Hour/4)) + + want := ratelimit.Counts{Minute: 1, Hour: 3.25, Day: 4} + if counts != want { + t.Errorf("counts %+v, want %+v", counts, want) + } +} + func TestResetSetsTheCountsBackToZero(t *testing.T) { t.Parallel() @@ -238,7 +261,7 @@ func wantCount( ) { t.Helper() - hit, _ := limiter.Count(client, now) + _, hit, _ := limiter.Count(client, now) if hit.Window != want { t.Errorf("request from %s at %s is over %q, want %q", client, now.Format(time.RFC3339), hit.Window, want) diff --git a/internal/requestlog/requestlog.go b/internal/requestlog/requestlog.go index f552c20..a36003a 100644 --- a/internal/requestlog/requestlog.go +++ b/internal/requestlog/requestlog.go @@ -9,6 +9,8 @@ import ( "io" "log/slog" "time" + + "sneak.berlin/go/smallwebwaf/internal/ratelimit" ) // The action a request line names: what smallwebwaf did with the @@ -45,32 +47,71 @@ const OffenceLimit = "limit" // timeLayout is RFC 3339 with milliseconds. const timeLayout = "2006-01-02T15:04:05.000Z07:00" -// Line is one request's line in the request log. The field names are -// those of the "Request log" section of SPEC.md. +// Line is one request's line in the request log. The field names, and +// their order, are those of the "Request log" section of SPEC.md. A field +// that may not apply to a request is left out of its line when it does +// not. // //nolint:tagliatelle // SPEC.md's request log names its fields in snake_case type Line struct { - Type string `json:"type"` - Time string `json:"time"` - ClientIP string `json:"client_ip"` - PeerIP string `json:"peer_ip"` - Country string `json:"country"` - Method string `json:"method"` - Host string `json:"host"` - Path string `json:"path"` - Query string `json:"query"` - Protocol string `json:"protocol"` - Status int `json:"status"` - UpstreamStatus int `json:"upstream_status,omitempty"` - RequestBytes int64 `json:"request_bytes"` - ResponseBytes int64 `json:"response_bytes"` - Referer string `json:"referer"` - UserAgent string `json:"user_agent"` - Action string `json:"action"` + Type string `json:"type"` + + // The standard web log fields. Scheme is how the client reached + // smallwebwaf, or the trusted proxy in front of it. + Time string `json:"time"` + Instance string `json:"instance"` + ClientIP string `json:"client_ip"` + Method string `json:"method"` + Scheme string `json:"scheme"` + Host string `json:"host"` + Path string `json:"path"` + Query string `json:"query"` + Protocol string `json:"protocol"` + Status int `json:"status"` + RequestBytes int64 `json:"request_bytes"` + ResponseBytes int64 `json:"response_bytes"` + Referer string `json:"referer"` + UserAgent string `json:"user_agent"` + + // Request detail. RequestID is the X-Request-ID a trusted proxy sent, + // or a new one, and is sent on to the app. ForwardedFor is the + // X-Forwarded-For header as received. ClientGroup is the netblock the + // client is counted as. + RequestID string `json:"request_id"` + PeerIP string `json:"peer_ip"` + ForwardedFor string `json:"forwarded_for,omitempty"` + ClientGroup string `json:"client_group"` + Country string `json:"country"` + ContentType string `json:"content_type,omitempty"` + // ContentLength is the length of its body the request announced. + ContentLength int64 `json:"content_length,omitempty"` + // RequestHeaders are the headers SWWAF_LOG_REQUEST_HEADERS names that + // the request carried, by name in lower case. + RequestHeaders map[string]string `json:"request_headers,omitempty"` + HasAuthorization bool `json:"has_authorization,omitempty"` + HasCookie bool `json:"has_cookie,omitempty"` + // Websocket is true when the connection was upgraded, as for a + // WebSocket. + Websocket bool `json:"websocket,omitempty"` + + // Response detail, from the headers of the answer: the app's, as + // passed on, or those of smallwebwaf's own. Aborted is true when the + // client went away early. + ResponseContentType string `json:"response_content_type,omitempty"` + UpstreamStatus int `json:"upstream_status,omitempty"` + CacheControl string `json:"cache_control,omitempty"` + Location string `json:"location,omitempty"` + Aborted bool `json:"aborted,omitempty"` + + // The decision. + Action string `json:"action"` // WouldAction is, in observe mode, the action enforce mode would have // taken with a request it would have refused: ActionDenied, // ActionBanned, ActionCountryDenied or ActionRateLimited. WouldAction string `json:"would_action,omitempty"` + // Counts are the client's requests as the rate limits counted them + // with this one, for a request they counted. + Counts ratelimit.Counts `json:"counts,omitzero"` // LimitHit is the window whose rate limit the request went over: // minute, hour or day. LimitHit string `json:"limit_hit,omitempty"` @@ -79,11 +120,18 @@ type Line struct { // BanExpires is when the ban the request made, or was refused under, // ends: a time, or "permanent". BanExpires string `json:"ban_expires,omitempty"` - // Aborted is true when the client went away early. - Aborted bool `json:"aborted,omitempty"` - // DurationTotal and DurationUpstreamTotal are in milliseconds. - DurationTotal float64 `json:"duration_total"` - DurationUpstreamTotal float64 `json:"duration_upstream_total,omitempty"` + + // The timings, in milliseconds. DurationChecks is the time until the + // checks were done. DurationUpstreamConnect, DurationUpstreamFirstByte + // and DurationUpstreamTotal run from when the request was handed to the + // app: until there was a connection to it, until the first byte of its + // answer arrived, and until the end. Each but DurationTotal is nil for + // a request that did not get that far. + DurationTotal float64 `json:"duration_total"` + DurationChecks *float64 `json:"duration_checks,omitempty"` + DurationUpstreamConnect *float64 `json:"duration_upstream_connect,omitempty"` + DurationUpstreamFirstByte *float64 `json:"duration_upstream_first_byte,omitempty"` + DurationUpstreamTotal *float64 `json:"duration_upstream_total,omitempty"` } // Write writes line to w as one JSON line marked "type":"request". diff --git a/internal/requestlog/requestlog_test.go b/internal/requestlog/requestlog_test.go index 897f4b7..38303b6 100644 --- a/internal/requestlog/requestlog_test.go +++ b/internal/requestlog/requestlog_test.go @@ -50,7 +50,11 @@ func TestWriteWritesOneJSONLineMarkedRequest(t *testing.T) { } unset := []string{ - "upstream_status", "limit_hit", "offence", "ban_expires", "aborted", + "forwarded_for", "content_type", "content_length", "request_headers", + "has_authorization", "has_cookie", "websocket", "response_content_type", + "upstream_status", "cache_control", "location", "aborted", "counts", + "limit_hit", "offence", "ban_expires", "duration_checks", + "duration_upstream_connect", "duration_upstream_first_byte", "duration_upstream_total", } for _, name := range unset {