diff --git a/internal/federationdomain/requestlogger/request_logger.go b/internal/federationdomain/requestlogger/request_logger.go index 34ada1034..ab6be586f 100644 --- a/internal/federationdomain/requestlogger/request_logger.go +++ b/internal/federationdomain/requestlogger/request_logger.go @@ -1,4 +1,4 @@ -// Copyright 2024 the Pinniped contributors. All Rights Reserved. +// Copyright 2024-2025 the Pinniped contributors. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 package requestlogger @@ -11,6 +11,7 @@ import ( "slices" "time" + utilnet "k8s.io/apimachinery/pkg/util/net" "k8s.io/apiserver/pkg/endpoints/responsewriter" "k8s.io/utils/clock" @@ -89,11 +90,23 @@ func (rl *requestLogger) logRequestReceived() { "serverName", requestutil.SNIServerName(r), "path", r.URL.Path, "userAgent", rl.userAgent, - "remoteAddr", r.RemoteAddr, + "sourceIPs", sourceIPs(r), }, }) } +func sourceIPs(r *http.Request) []string { + // Use the same utility function that calculate the sourceIPs field in the Kubernetes audit logs. + // See "sourceIPs" in https://kubernetes.io/docs/reference/config-api/apiserver-audit.v1 for docs. + // This can log useful information when the request was made through a proxy. + ips := utilnet.SourceIPs(r) + ipsAsStr := make([]string, len(ips)) + for i := range ips { + ipsAsStr[i] = ips[i].String() + } + return ipsAsStr +} + func getLocationForAuditLogs(location string) string { if location == "" { return "no location header" diff --git a/internal/federationdomain/requestlogger/request_logger_test.go b/internal/federationdomain/requestlogger/request_logger_test.go index ccf986aed..9d2b338e2 100644 --- a/internal/federationdomain/requestlogger/request_logger_test.go +++ b/internal/federationdomain/requestlogger/request_logger_test.go @@ -1,4 +1,4 @@ -// Copyright 2024 the Pinniped contributors. All Rights Reserved. +// Copyright 2024-2025 the Pinniped contributors. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 package requestlogger @@ -21,7 +21,7 @@ import ( func TestLogRequestReceived(t *testing.T) { var noAuditEventsWanted []testutil.WantedAuditLog - happyAuditEventWanted := func(path string) []testutil.WantedAuditLog { + happyAuditEventWanted := func(path string, sourceIPs []any) []testutil.WantedAuditLog { return []testutil.WantedAuditLog{ testutil.WantAuditLog("HTTP Request Received", map[string]any{ @@ -31,7 +31,7 @@ func TestLogRequestReceived(t *testing.T) { "serverName": "some-sni-server-name", "path": path, "userAgent": "some-user-agent", - "remoteAddr": "some-remote-addr", + "sourceIPs": sourceIPs, }, ), } @@ -39,33 +39,84 @@ func TestLogRequestReceived(t *testing.T) { tests := []struct { name string - path string + reqPath string + reqRemoteAddr string + reqHeaders map[string][]string auditInternalPaths bool wantAuditLogs []testutil.WantedAuditLog }{ { name: "when internal paths are not enabled, ignores internal paths", - path: "/healthz", + reqPath: "/healthz", auditInternalPaths: false, wantAuditLogs: noAuditEventsWanted, }, { name: "when internal paths are not enabled, audits external path", - path: "/pretend-to-login", + reqPath: "/pretend-to-login", + reqRemoteAddr: "1.2.3.4", auditInternalPaths: false, - wantAuditLogs: happyAuditEventWanted("/pretend-to-login"), + wantAuditLogs: happyAuditEventWanted("/pretend-to-login", []any{"1.2.3.4"}), }, { name: "when internal paths are enabled, audits internal paths", - path: "/healthz", + reqPath: "/healthz", + reqRemoteAddr: "1.2.3.4", auditInternalPaths: true, - wantAuditLogs: happyAuditEventWanted("/healthz"), + wantAuditLogs: happyAuditEventWanted("/healthz", []any{"1.2.3.4"}), }, { name: "when internal paths are enabled, audits external paths", - path: "/pretend-to-login", + reqPath: "/pretend-to-login", + reqRemoteAddr: "1.2.3.4", auditInternalPaths: true, - wantAuditLogs: happyAuditEventWanted("/pretend-to-login"), + wantAuditLogs: happyAuditEventWanted("/pretend-to-login", []any{"1.2.3.4"}), + }, + { + name: "when X-Forwarded-For header is present, includes its values in sourceIPs before the remoteAddr", + reqPath: "/pretend-to-login", + reqRemoteAddr: "1.2.3.4", + reqHeaders: map[string][]string{"X-Forwarded-For": {"5.6.7.8, 9.10.11.12"}}, + auditInternalPaths: true, + wantAuditLogs: happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "9.10.11.12", "1.2.3.4"}), + }, + { + name: "when X-Real-Ip header is present, includes its value in sourceIPs before the remoteAddr", + reqPath: "/pretend-to-login", + reqRemoteAddr: "1.2.3.4", + reqHeaders: map[string][]string{"X-Real-Ip": {"5.6.7.8"}}, + auditInternalPaths: true, + wantAuditLogs: happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "1.2.3.4"}), + }, + { + name: "when both X-Forwarded-For and X-Real-Ip headers are present, includes both headers' values in sourceIPs before the remoteAddr", + reqPath: "/pretend-to-login", + reqRemoteAddr: "1.2.3.4", + reqHeaders: map[string][]string{ + "X-Forwarded-For": {"5.6.7.8, 9.10.11.12"}, + "X-Real-Ip": {"13.14.15.16"}, + }, + auditInternalPaths: true, + wantAuditLogs: happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "9.10.11.12", "13.14.15.16", "1.2.3.4"}), + }, + { + name: "when the X-Real-Ip is the same as remoteAddr, does not duplicate remoteAddr", + reqPath: "/pretend-to-login", + reqRemoteAddr: "1.2.3.4", + reqHeaders: map[string][]string{ + "X-Forwarded-For": {"5.6.7.8, 9.10.11.12"}, + "X-Real-Ip": {"1.2.3.4"}, + }, + auditInternalPaths: true, + wantAuditLogs: happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "9.10.11.12", "1.2.3.4"}), + }, + { + name: "when the last value of X-Forwarded-For is the same as remoteAddr and there is no X-Real-Ip, does not duplicate remoteAddr", + reqPath: "/pretend-to-login", + reqRemoteAddr: "1.2.3.4", + reqHeaders: map[string][]string{"X-Forwarded-For": {"5.6.7.8, 1.2.3.4"}}, + auditInternalPaths: true, + wantAuditLogs: happyAuditEventWanted("/pretend-to-login", []any{"5.6.7.8", "1.2.3.4"}), }, } @@ -81,9 +132,10 @@ func TestLogRequestReceived(t *testing.T) { Proto: "some-proto", Host: "some-host", URL: &url.URL{ - Path: test.path, + Path: test.reqPath, }, - RemoteAddr: "some-remote-addr", + RemoteAddr: test.reqRemoteAddr, + Header: test.reqHeaders, TLS: &tls.ConnectionState{ ServerName: "some-sni-server-name", }, @@ -119,52 +171,52 @@ func TestLogRequestComplete(t *testing.T) { tests := []struct { name string - path string + reqPath string location string auditInternalPaths bool wantAuditLogs []testutil.WantedAuditLog }{ { name: "when internal paths are not enabled, ignores internal paths", - path: "/healthz", + reqPath: "/healthz", auditInternalPaths: false, wantAuditLogs: noAuditEventsWanted, }, { name: "when internal paths are not enabled, audits external path with location (redacting unknown query params)", - path: "/pretend-to-login", + reqPath: "/pretend-to-login", location: "http://127.0.0.1?foo=bar&foo=quz&lorem=ipsum", auditInternalPaths: false, wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "http://127.0.0.1?foo=redacted&foo=redacted&lorem=redacted"), }, { name: "when internal paths are enabled, audits internal paths", - path: "/healthz", + reqPath: "/healthz", auditInternalPaths: true, wantAuditLogs: happyAuditEventWanted("/healthz", "no location header"), }, { name: "when internal paths are enabled, audits external paths", - path: "/pretend-to-login", + reqPath: "/pretend-to-login", location: "some-location", auditInternalPaths: true, wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "some-location"), }, { name: "audits path without location", - path: "/pretend-to-login", + reqPath: "/pretend-to-login", location: "", // make it obvious wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "no location header"), }, { name: "audits path with invalid location", - path: "/pretend-to-login", + reqPath: "/pretend-to-login", location: "http://e x a m p l e.com", wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "unparsable location header"), }, { name: "audits path with location redacting all query params except err, error, and error_description", - path: "/pretend-to-login", + reqPath: "/pretend-to-login", location: "http://127.0.0.1:1234?code=pin_ac_FAKE&foo=bar&foo=quz&lorem=ipsum&err=some-err&error=some-error&error_description=some-error-description&zzlast=some-value", wantAuditLogs: happyAuditEventWanted("/pretend-to-login", "http://127.0.0.1:1234?code=redacted&err=some-err&error=some-error&error_description=some-error-description&foo=redacted&foo=redacted&lorem=redacted&zzlast=redacted"), }, @@ -194,7 +246,7 @@ func TestLogRequestComplete(t *testing.T) { clock: frozenClock, req: &http.Request{ URL: &url.URL{ - Path: test.path, + Path: test.reqPath, }, }, status: 777, diff --git a/site/content/docs/reference/audit-logging.md b/site/content/docs/reference/audit-logging.md index c3ab8c2ed..755c6e276 100644 --- a/site/content/docs/reference/audit-logging.md +++ b/site/content/docs/reference/audit-logging.md @@ -98,6 +98,12 @@ correlate an audit event log line to other logs. The values for these keys are o Each audit event may also have more key-value pairs specific to the event's type. +- Some audit logs for the Supervisor contain a `sourceIPs` key. + The value at this key is calculated using the same method as the `sourceIPs` + field in the Kubernetes audit logs. See the definition of the `sourceIPs` field in + [the Kubernetes auditing documentation](https://kubernetes.io/docs/reference/config-api/apiserver-audit.v1/) + for details. + ## Configuration options for audit events Logging of audit events is always enabled. There are two configuration options available: @@ -176,7 +182,7 @@ The logs from the authorize endpoint are shown below. "serverName": "example-supervisor.pinniped.dev", "path": "/oauth2/authorize", "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.1.1 Safari/605.1.15", - "remoteAddr": "1.2.3.4:58586" + "sourceIPs": [ "1.2.3.4:58586" ] } { "level": "info", @@ -258,7 +264,7 @@ with the logs from this callback request, shown below. "serverName": "example-supervisor.pinniped.dev", "path": "/callback", "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.1.1 Safari/605.1.15", - "remoteAddr": "1.2.3.4:58586" + "sourceIPs": [ "1.2.3.4:58586" ] } { "level": "info", @@ -354,7 +360,7 @@ The logs from the token endpoint are shown below. "serverName": "example-supervisor.pinniped.dev", "path": "/oauth2/token", "userAgent": "pinniped/v0.0.0 (darwin/arm64) kubernetes/$Format", - "remoteAddr": "1.2.3.4:59420" + "sourceIPs": [ "1.2.3.4:59420" ] } { "level": "info", @@ -423,7 +429,7 @@ for the target workload cluster (technically, an ID token with a different `aud` "serverName": "example-supervisor.pinniped.dev", "path": "/oauth2/token", "userAgent": "pinniped/v0.0.0 (darwin/arm64) kubernetes/$Format", - "remoteAddr": "1.2.3.4:59420" + "sourceIPs": [ "1.2.3.4:59420" ] } { "level": "info", diff --git a/test/integration/audit_test.go b/test/integration/audit_test.go index 4e7cd7aef..68c6f7652 100644 --- a/test/integration/audit_test.go +++ b/test/integration/audit_test.go @@ -1,4 +1,4 @@ -// Copyright 2024 the Pinniped contributors. All Rights Reserved. +// Copyright 2024-2025 the Pinniped contributors. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 package integration @@ -702,7 +702,7 @@ func removeSomeKeysFromEachAuditLogEvent(logs []map[string]any) { delete(log, "level") delete(log, "auditEvent") delete(log, "caller") - delete(log, "remoteAddr") + delete(log, "sourceIPs") delete(log, "userAgent") delete(log, "timestamp") delete(log, "latency")