change remoteAddr to sourceIPs in Supervisor audit log for incoming reqs

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"

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,

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",

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")