resolve some todos

internal/controller/supervisorstorage/garbage_collector.go

@@ -283,7 +283,7 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken(
 		if err != nil {
 			return err
 		}
-		c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, nil, request,
+		c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, plog.NoHTTPRequestAvailable(), request,
 			"type", upstreamprovider.RefreshTokenType)
 		plog.Trace("garbage collector successfully revoked upstream OIDC refresh token (or provider has no revocation endpoint)", logKV(secret)...)
 	}
@@ -293,7 +293,7 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken(
 		if err != nil {
 			return err
 		}
-		c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, nil, request,
+		c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, plog.NoHTTPRequestAvailable(), request,
 			"type", upstreamprovider.AccessTokenType)
 		plog.Trace("garbage collector successfully revoked upstream OIDC access token (or provider has no revocation endpoint)", logKV(secret)...)
 	}
@@ -304,7 +304,8 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken(
 func (c *garbageCollectorController) maybeAuditLogGC(storageType string, secret *corev1.Secret) {
 	r, err := c.requestFromSecret(storageType, secret)
 	if err == nil && r != nil {
-		c.auditLogger.Audit(plog.AuditEventSessionGarbageCollected, nil, r, "storageType", storageType)
+		c.auditLogger.Audit(plog.AuditEventSessionGarbageCollected, plog.NoHTTPRequestAvailable(), r,
+			"storageType", storageType)
 	}
 }
 

internal/federationdomain/endpoints/auth/auth_handler_test.go

@@ -35,6 +35,7 @@ import (
 	"go.pinniped.dev/internal/federationdomain/endpoints/jwks"
 	"go.pinniped.dev/internal/federationdomain/oidc"
 	"go.pinniped.dev/internal/federationdomain/oidcclientvalidator"
+	"go.pinniped.dev/internal/federationdomain/requestlogger"
 	"go.pinniped.dev/internal/federationdomain/stateparam"
 	"go.pinniped.dev/internal/federationdomain/storage"
 	"go.pinniped.dev/internal/here"
@@ -3803,6 +3804,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo
 		if test.customPasswordHeader != nil {
 			req.Header.Set("Pinniped-Password", *test.customPasswordHeader)
 		}
+		req, _ = requestlogger.NewRequestWithAuditID(req, func() string { return "fake-audit-id" })
 		rsp := httptest.NewRecorder()
 
 		subject.ServeHTTP(rsp, req)
@@ -3874,6 +3876,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo
 
 		if test.wantAuditLogs != nil {
 			wantAuditLogs := test.wantAuditLogs(stateparam.Encoded(actualQueryStateParam), sessionID)
+			testutil.WantAuditIDOnEveryAuditLog(wantAuditLogs, "fake-audit-id")
 			testutil.CompareAuditLogs(t, wantAuditLogs, auditLog.String())
 		}
 

internal/federationdomain/endpoints/callback/callback_handler_test.go

@@ -25,6 +25,7 @@ import (
 	"go.pinniped.dev/internal/federationdomain/endpoints/jwks"
 	"go.pinniped.dev/internal/federationdomain/oidc"
 	"go.pinniped.dev/internal/federationdomain/oidcclientvalidator"
+	"go.pinniped.dev/internal/federationdomain/requestlogger"
 	"go.pinniped.dev/internal/federationdomain/stateparam"
 	"go.pinniped.dev/internal/federationdomain/storage"
 	"go.pinniped.dev/internal/federationdomain/upstreamprovider"
@@ -1868,6 +1869,7 @@ func TestCallbackEndpoint(t *testing.T) {
 			if test.csrfCookie != "" {
 				req.Header.Set("Cookie", test.csrfCookie)
 			}
+			req, _ = requestlogger.NewRequestWithAuditID(req, func() string { return "fake-audit-id" })
 			rsp := httptest.NewRecorder()
 			subject.ServeHTTP(rsp, req)
 			t.Logf("response: %#v", rsp)
@@ -1877,13 +1879,13 @@ func TestCallbackEndpoint(t *testing.T) {
 
 			switch {
 			case test.wantOIDCAuthcodeExchangeCall != nil:
-				test.wantOIDCAuthcodeExchangeCall.args.Ctx = reqContext
+				test.wantOIDCAuthcodeExchangeCall.args.Ctx = req.Context()
 				test.idps.RequireExactlyOneOIDCAuthcodeExchange(t,
 					test.wantOIDCAuthcodeExchangeCall.performedByUpstreamName,
 					test.wantOIDCAuthcodeExchangeCall.args,
 				)
 			case test.wantGitHubAuthcodeExchangeCall != nil:
-				test.wantGitHubAuthcodeExchangeCall.args.Ctx = reqContext
+				test.wantGitHubAuthcodeExchangeCall.args.Ctx = req.Context()
 				test.idps.RequireExactlyOneGitHubAuthcodeExchange(t,
 					test.wantGitHubAuthcodeExchangeCall.performedByUpstreamName,
 					test.wantGitHubAuthcodeExchangeCall.args,
@@ -1956,6 +1958,7 @@ func TestCallbackEndpoint(t *testing.T) {
 
 			if test.wantAuditLogs != nil {
 				wantAuditLogs := test.wantAuditLogs(testutil.GetStateParam(t, test.path), sessionID)
+				testutil.WantAuditIDOnEveryAuditLog(wantAuditLogs, "fake-audit-id")
 				testutil.CompareAuditLogs(t, wantAuditLogs, log.String())
 			}
 		})

internal/federationdomain/endpoints/login/login_handler_test.go

@@ -14,6 +14,7 @@ import (
 	"github.com/stretchr/testify/require"
 
 	"go.pinniped.dev/internal/federationdomain/oidc"
+	"go.pinniped.dev/internal/federationdomain/requestlogger"
 	"go.pinniped.dev/internal/federationdomain/stateparam"
 	"go.pinniped.dev/internal/httputil/httperr"
 	"go.pinniped.dev/internal/plog"
@@ -411,6 +412,7 @@ func TestLoginEndpoint(t *testing.T) {
 			if test.csrfCookie != "" {
 				req.Header.Set("Cookie", test.csrfCookie)
 			}
+			req, _ = requestlogger.NewRequestWithAuditID(req, func() string { return "fake-audit-id" })
 			rsp := httptest.NewRecorder()
 
 			testGetHandler := func(
@@ -465,6 +467,7 @@ func TestLoginEndpoint(t *testing.T) {
 
 			if test.wantAuditLogs != nil {
 				wantAuditLogs := test.wantAuditLogs(testutil.GetStateParam(t, test.path))
+				testutil.WantAuditIDOnEveryAuditLog(wantAuditLogs, "fake-audit-id")
 				testutil.CompareAuditLogs(t, wantAuditLogs, log.String())
 			}
 		})

internal/federationdomain/endpointsmanager/manager.go

@@ -8,7 +8,6 @@ import (
 	"strings"
 	"sync"
 
-	"github.com/google/uuid"
 	corev1client "k8s.io/client-go/kubernetes/typed/core/v1"
 
 	"go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned/typed/config/v1alpha1"
@@ -29,7 +28,6 @@ import (
 	"go.pinniped.dev/internal/federationdomain/oidcclientvalidator"
 	"go.pinniped.dev/internal/federationdomain/requestlogger"
 	"go.pinniped.dev/internal/federationdomain/storage"
-	"go.pinniped.dev/internal/httputil/requestutil"
 	"go.pinniped.dev/internal/plog"
 	"go.pinniped.dev/internal/secret"
 	"go.pinniped.dev/pkg/oidcclient/nonce"
@@ -194,36 +192,24 @@ func (m *Manager) SetFederationDomains(federationDomains ...*federationdomainpro
 }
 
 func (m *Manager) buildHandlerChain(nextHandler http.Handler, auditCfg supervisor.AuditSpec) {
-	// build the basic handler for FederationDomain endpoints
+	// Build the basic handler for FederationDomain endpoints.
 	handler := m.buildManagerHandler(nextHandler)
-	// log all requests, including audit ID
+	// Log all requests, including audit ID.
 	handler = requestlogger.WithHTTPRequestAuditLogging(handler, m.auditLogger, auditCfg)
-	// add random audit ID to request context and response headers
-	handler = requestlogger.WithAuditID(handler, func() string {
-		return uuid.New().String()
-	})
+	// Add random audit ID to request context and response headers.
+	handler = requestlogger.WithAuditID(handler)
 	m.handlerChain = handler
 }
 
 func (m *Manager) buildManagerHandler(nextHandler http.Handler) http.Handler {
 	return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
 		requestHandler := m.findHandler(req)
-
-		// TODO: Should this old log message change in light of the new audit logs? Or do we not want to force people to enable audit logs to debug this SNI stuff?
-		// Using Info level so the user can safely configure a production Supervisor to show this message if they choose.
-		plog.Info("received incoming request",
-			"proto", req.Proto,
-			"method", req.Method,
-			"host", req.Host,
-			"requestSNIServerName", requestutil.SNIServerName(req),
-			"path", req.URL.Path,
-			"remoteAddr", req.RemoteAddr,
-			"userAgent", req.UserAgent(),
-			"foundFederationDomainRequestHandler", requestHandler != nil,
-		)
-
 		if requestHandler == nil {
-			requestHandler = nextHandler // couldn't find an issuer to handle the request
+			// Couldn't find any FederationDomain to handle this request based on the request's host and path.
+			// It could be a bad request to a path that does not exist. Or it could be because something in
+			// front of the Supervisor is not passing the SNI of the original request through to the Supervisor.
+			// All 404's will be logged by request_logger.go, so we don't need to log it here.
+			requestHandler = nextHandler
 		}
 		requestHandler.ServeHTTP(resp, req)
 	})

internal/federationdomain/requestlogger/request_logger.go

@@ -11,6 +11,7 @@ import (
 	"slices"
 	"time"
 
+	"github.com/google/uuid"
 	"k8s.io/apimachinery/pkg/types"
 	"k8s.io/apimachinery/pkg/util/sets"
 	apisaudit "k8s.io/apiserver/pkg/apis/audit"
@@ -23,6 +24,7 @@ import (
 	"go.pinniped.dev/internal/plog"
 )
 
+// NewRequestWithAuditID is public for use in unit tests. Production code should use WithAuditID().
 func NewRequestWithAuditID(r *http.Request, newAuditIDFunc func() string) (*http.Request, string) {
 	ctx := audit.WithAuditContext(r.Context())
 	r = r.WithContext(ctx)
@@ -33,9 +35,12 @@ func NewRequestWithAuditID(r *http.Request, newAuditIDFunc func() string) (*http
 	return r, auditID
 }
 
-func WithAuditID(handler http.Handler, newAuditIDFunc func() string) http.Handler {
+func WithAuditID(handler http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		r, auditID := NewRequestWithAuditID(r, newAuditIDFunc)
+		// Add a randomly generated request ID to the context for this request.
+		r, auditID := NewRequestWithAuditID(r, func() string {
+			return uuid.New().String()
+		})
 
 		// Send the Audit-ID response header.
 		w.Header().Set(apisaudit.HeaderAuditID, auditID)
@@ -48,8 +53,8 @@ func WithHTTPRequestAuditLogging(handler http.Handler, auditLogger plog.AuditLog
 	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 		rl := newRequestLogger(req, w, auditLogger, time.Now(), auditCfg)
 
-		rl.LogRequestReceived()
-		defer rl.LogRequestComplete()
+		rl.logRequestReceived()
+		defer rl.logRequestComplete()
 
 		statusCodeCapturingResponseWriter := responsewriter.WrapForHTTP1Or2(rl)
 		handler.ServeHTTP(statusCodeCapturingResponseWriter, req)
@@ -90,13 +95,14 @@ func internalPaths() []string {
 	}
 }
 
-func (rl *requestLogger) LogRequestReceived() {
+func (rl *requestLogger) logRequestReceived() {
 	r := rl.req
 
 	if rl.auditCfg.InternalPaths != supervisor.AuditInternalPathsEnabled && slices.Contains(internalPaths(), r.URL.Path) {
 		return
 	}
 
+	// Always log all other requests, including 404's caused by bad paths, for debugging purposes.
 	rl.auditLogger.Audit(plog.AuditEventHTTPRequestReceived,
 		r.Context(),
 		plog.NoSessionPersisted(),
@@ -110,7 +116,7 @@ func (rl *requestLogger) LogRequestReceived() {
 	)
 }
 
-func (rl *requestLogger) LogRequestComplete() {
+func (rl *requestLogger) logRequestComplete() {
 	r := rl.req
 
 	if rl.auditCfg.InternalPaths != supervisor.AuditInternalPathsEnabled && slices.Contains(internalPaths(), r.URL.Path) {

internal/federationdomain/requestlogger/request_logger_test.go

@@ -98,7 +98,7 @@ func TestLogRequestReceived(t *testing.T) {
 				auditCfg:  test.auditCfg,
 			}
 
-			subject.LogRequestReceived()
+			subject.logRequestReceived()
 
 			testutil.CompareAuditLogs(t, test.wantAuditLogs, log.String())
 		})
@@ -217,7 +217,7 @@ func TestLogRequestComplete(t *testing.T) {
 				auditCfg: test.auditCfg,
 			}
 
-			subject.LogRequestComplete()
+			subject.logRequestComplete()
 
 			testutil.CompareAuditLogs(t, test.wantAuditLogs, log.String())
 		})

internal/plog/plog.go

@@ -126,7 +126,6 @@ func (p pLogger) Error(msg string, err error, keysAndValues ...any) {
 // by their own separate configuration. This is because Audit logs should always be printed when they are desired
 // by the admin, regardless of global log level, yet the admin should also have a way to entirely disable them
 // when they want to avoid potential PII (e.g. usernames) in their pod logs.
-// TODO: Add a way to disable output of audit logs, separate from the log level config.
 func (p pLogger) Audit(msg AuditEventMessage, reqCtx context.Context, session SessionIDGetter, keysAndValues ...any) {
 	// Always add a key/value auditEvent=true.
 	keysAndValues = slices.Concat([]any{"auditEvent", true}, keysAndValues)

internal/testutil/log_lines.go

@@ -30,17 +30,20 @@ type WantedAuditLog struct {
 	Params  map[string]any
 }
 
-func WantAuditLog(message string, params map[string]any, auditID ...string) WantedAuditLog {
+func WantAuditLog(message string, params map[string]any) WantedAuditLog {
 	result := WantedAuditLog{
 		Message: message,
 		Params:  params,
 	}
-	if len(auditID) > 0 {
-		result.Params["auditID"] = auditID[0]
-	}
 	return result
 }
 
+func WantAuditIDOnEveryAuditLog(wantedAuditLogs []WantedAuditLog, wantAuditID string) {
+	for _, wantedAuditLog := range wantedAuditLogs {
+		wantedAuditLog.Params["auditID"] = wantAuditID
+	}
+}
+
 func GetStateParam(t *testing.T, fullURL string) stateparam.Encoded {
 	var encodedStateParam stateparam.Encoded
 	if fullURL != "" {

site/content/docs/reference/audit-logging.md

@@ -64,7 +64,7 @@ Every log line in a Supervisor or Concierge pod log is a JSON object. Only those
 key/value pair `"auditEvent": true` are audit events. Other lines are for errors, warnings, and
 debugging information.
 
-Every audit log contains the following keys, and audit event lines also contain these common keys/values:
+Every line in the pod logs contains the following common keys/values, including audit event log lines:
 
 - `timestamp`, whose value is in UTC time, e.g. `2024-07-10T20:03:26.164470Z`
 - `level`, which for an audit event will always have the value `info`