Log params to token_handler endpoint even during error cases

internal/federationdomain/endpoints/auth/auth_handler_test.go

@@ -272,14 +272,14 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo
 		// Inject this into our test subject at the last second so we get a fresh storage for every test.
 		// Use lower minimum required bcrypt cost than we would use in production to keep unit the tests fast.
 		kubeOauthStore := storage.NewKubeStorage(secretsClient, oidcClientsClient, timeoutsConfiguration, bcrypt.MinCost)
-		return oidc.FositeOauth2Helper(kubeOauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration), kubeOauthStore
+		return oidc.FositeOauth2Helper(kubeOauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration, nil), kubeOauthStore
 	}
 
 	createOauthHelperWithNullStorage := func(secretsClient v1.SecretInterface, oidcClientsClient v1alpha1.OIDCClientInterface) (fosite.OAuth2Provider, *storage.NullStorage) {
 		// Configure fosite the same way that the production code would, using NullStorage to turn off storage.
 		// Use lower minimum required bcrypt cost than we would use in production to keep unit the tests fast.
 		nullOauthStore := storage.NewNullStorage(secretsClient, oidcClientsClient, bcrypt.MinCost)
-		return oidc.FositeOauth2Helper(nullOauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration), nullOauthStore
+		return oidc.FositeOauth2Helper(nullOauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration, nil), nullOauthStore
 	}
 
 	upstreamAuthURL, err := url.Parse("https://some-upstream-idp:8443/auth")

internal/federationdomain/endpoints/callback/callback_handler_test.go

@@ -1851,7 +1851,7 @@ func TestCallbackEndpoint(t *testing.T) {
 			hmacSecretFunc := func() []byte { return []byte("some secret - must have at least 32 bytes") }
 			require.GreaterOrEqual(t, len(hmacSecretFunc()), 32, "fosite requires that hmac secrets have at least 32 bytes")
 			jwksProviderIsUnused := jwks.NewDynamicJWKSProvider()
-			oauthHelper := oidc.FositeOauth2Helper(oauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration)
+			oauthHelper := oidc.FositeOauth2Helper(oauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration, nil)
 
 			logger, log := plog.TestLogger(t)
 

internal/federationdomain/endpoints/login/post_login_handler_test.go

@@ -1137,7 +1137,7 @@ func TestPostLoginEndpoint(t *testing.T) {
 			hmacSecretFunc := func() []byte { return []byte("some secret - must have at least 32 bytes") }
 			require.GreaterOrEqual(t, len(hmacSecretFunc()), 32, "fosite requires that hmac secrets have at least 32 bytes")
 			jwksProviderIsUnused := jwks.NewDynamicJWKSProvider()
-			oauthHelper := oidc.FositeOauth2Helper(kubeOauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration)
+			oauthHelper := oidc.FositeOauth2Helper(kubeOauthStore, downstreamIssuer, hmacSecretFunc, jwksProviderIsUnused, timeoutsConfiguration, nil)
 
 			req := httptest.NewRequest(http.MethodPost, "/ignored", strings.NewReader(tt.formParams.Encode()))
 			req.Header.Set("Content-Type", "application/x-www-form-urlencoded")

internal/federationdomain/endpoints/token/token_handler.go

@@ -30,18 +30,6 @@ import (
 	"go.pinniped.dev/internal/psession"
 )
 
-func paramsSafeToLog() sets.Set[string] {
-	return sets.New(
-		// Standard params from https://openid.net/specs/openid-connect-core-1_0.html for authcode and refresh grants.
-		// Redacting code, client_secret, refresh_token, and PKCE code_verifier params.
-		"grant_type", "client_id", "redirect_uri", "scope",
-		// Token exchange params from https://datatracker.ietf.org/doc/html/rfc8693.
-		// Redact subject_token and actor_token.
-		// We don't allow all of these, but they should be safe to log.
-		"audience", "resource", "scope", "requested_token_type", "actor_token_type", "subject_token_type",
-	)
-}
-
 func NewHandler(
 	idpLister federationdomainproviders.FederationDomainIdentityProvidersListerI,
 	oauthHelper fosite.OAuth2Provider,
@@ -58,10 +46,6 @@ func NewHandler(
 			return nil
 		}
 
-		// Note that r.PostForm and accessRequest were populated by NewAccessRequest().
-		auditLogger.Audit(plog.AuditEventHTTPRequestParameters, r.Context(), accessRequest,
-			"params", plog.SanitizeParams(r.PostForm, paramsSafeToLog()))
-
 		// Check if we are performing a refresh grant.
 		if accessRequest.GetGrantTypes().ExactOne(oidcapi.GrantTypeRefreshToken) {
 			// The above call to NewAccessRequest has loaded the session from storage into the accessRequest variable.
@@ -226,17 +210,19 @@ func upstreamRefresh(
 		refreshedIdentity.UpstreamGroups = oldUntransformedGroups
 	}
 
-	refreshedTransformedUsername, refreshedTransformedGroups, err := applyIdentityTransformationsDuringRefresh(ctx,
+	refreshedTransformedUsername, refreshedTransformedGroups, fositeErr := applyIdentityTransformationsDuringRefresh(ctx,
 		idp.GetTransforms(),
 		refreshedIdentity.UpstreamUsername,
 		refreshedIdentity.UpstreamGroups,
 		providerName,
 		providerType,
 	)
-	if err != nil {
+	if fositeErr != nil {
+		// The HintField is always populated by applyIdentityTransformationsDuringRefresh,
+		// and more descriptive than fositeErr.Error() which is just "error".
 		auditLogger.Audit(plog.AuditEventAuthenticationRejectedByTransforms, ctx, accessRequest,
-			"reason", err)
-		return err
+			"reason", fositeErr.HintField)
+		return fositeErr
 	}
 
 	if oldTransformedUsername != refreshedTransformedUsername {
@@ -299,7 +285,7 @@ func applyIdentityTransformationsDuringRefresh(
 	upstreamGroups []string,
 	providerName string,
 	providerType psession.ProviderType,
-) (string, []string, error) {
+) (string, []string, *fosite.RFC6749Error) {
 	transformationResult, err := transforms.Evaluate(ctx, upstreamUsername, upstreamGroups)
 	if err != nil {
 		return "", nil, errUpstreamRefreshError().WithHintf(

internal/federationdomain/endpoints/token/token_handler_test.go

@@ -389,8 +389,7 @@ func TestTokenEndpointAuthcodeExchange(t *testing.T) {
 					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
 						return []testutil.WantedAuditLog{
 							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
-								"sessionID": sessionID,
-								"params":    "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+								"params": "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
 							}),
 						}
 					},
@@ -454,8 +453,7 @@ func TestTokenEndpointAuthcodeExchange(t *testing.T) {
 					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
 						return []testutil.WantedAuditLog{
 							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
-								"sessionID": sessionID,
-								"params":    "code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+								"params": "code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
 							}),
 						}
 					},
@@ -540,8 +538,7 @@ func TestTokenEndpointAuthcodeExchange(t *testing.T) {
 					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
 						return []testutil.WantedAuditLog{
 							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
-								"sessionID": sessionID,
-								"params":    "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+								"params": "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
 							}),
 						}
 					},
@@ -937,6 +934,13 @@ func TestTokenEndpointAuthcodeExchange(t *testing.T) {
 				want: tokenEndpointResponseExpectedValues{
 					wantStatus:            http.StatusBadRequest,
 					wantErrorResponseBody: fositeMissingPKCEVerifierErrorBody,
+					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
+						return []testutil.WantedAuditLog{
+							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
+								"params": "client_id=pinniped-cli&code=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+							}),
+						}
+					},
 				},
 			},
 		},
@@ -951,6 +955,13 @@ func TestTokenEndpointAuthcodeExchange(t *testing.T) {
 				want: tokenEndpointResponseExpectedValues{
 					wantStatus:            http.StatusBadRequest,
 					wantErrorResponseBody: fositeWrongPKCEVerifierErrorBody,
+					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
+						return []testutil.WantedAuditLog{
+							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
+								"params": "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+							}),
+						}
+					},
 				},
 			},
 		},
@@ -1148,8 +1159,7 @@ func TestTokenEndpointTokenExchange(t *testing.T) { // tests for grant_type "urn
 					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
 						return []testutil.WantedAuditLog{
 							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
-								"sessionID": sessionID,
-								"params":    "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+								"params": "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
 							}),
 						}
 					},
@@ -1160,7 +1170,6 @@ func TestTokenEndpointTokenExchange(t *testing.T) { // tests for grant_type "urn
 			wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
 				return []testutil.WantedAuditLog{
 					testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
-						"sessionID": sessionID,
 						"params": func() string {
 							params := url.Values{}
 							params.Set("audience", "some-workload-cluster")
@@ -1347,6 +1356,21 @@ func TestTokenEndpointTokenExchange(t *testing.T) { // tests for grant_type "urn
 			wantStatus:            http.StatusBadRequest,
 			wantErrorType:         "unauthorized_client",
 			wantErrorDescContains: `The client is not authorized to request a token using this method. The OAuth 2.0 Client is not allowed to use token exchange grant 'urn:ietf:params:oauth:grant-type:token-exchange'.`,
+			wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
+				return []testutil.WantedAuditLog{
+					testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
+						"params": func() string {
+							params := url.Values{}
+							params.Set("audience", "some-workload-cluster")
+							params.Set("grant_type", "urn:ietf:params:oauth:grant-type:token-exchange")
+							params.Set("requested_token_type", "urn:ietf:params:oauth:token-type:jwt")
+							params.Set("subject_token", "redacted")
+							params.Set("subject_token_type", "urn:ietf:params:oauth:token-type:access_token")
+							return params.Encode()
+						}(),
+					}),
+				}
+			},
 		},
 		{
 			name:          "dynamic client did not ask for the pinniped:request-audience scope in the original authorization request, so the access token submitted during token exchange lacks the scope",
@@ -1445,6 +1469,22 @@ func TestTokenEndpointTokenExchange(t *testing.T) { // tests for grant_type "urn
 			wantStatus:            http.StatusBadRequest,
 			wantErrorType:         "invalid_request",
 			wantErrorDescContains: "Missing 'audience' parameter.",
+			wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
+				return []testutil.WantedAuditLog{
+					testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
+						"params": func() string {
+							params := url.Values{}
+							params.Set("audience", "") // make it obvious
+							params.Set("client_id", "pinniped-cli")
+							params.Set("grant_type", "urn:ietf:params:oauth:grant-type:token-exchange")
+							params.Set("requested_token_type", "urn:ietf:params:oauth:token-type:jwt")
+							params.Set("subject_token", "redacted")
+							params.Set("subject_token_type", "urn:ietf:params:oauth:token-type:access_token")
+							return params.Encode()
+						}(),
+					}),
+				}
+			},
 		},
 		{
 			name:                  "bad requested audience when it looks like the name of an OIDCClient CR",
@@ -1710,7 +1750,7 @@ func TestTokenEndpointTokenExchange(t *testing.T) { // tests for grant_type "urn
 			t.Parallel()
 
 			// Authcode exchange doesn't use the upstream provider cache, so just pass an empty cache.
-			subject, rsp, _, _, secrets, oauthStore, log, sessionID := exchangeAuthcodeForTokens(t,
+			subject, rsp, _, _, secrets, oauthStore, actualAuditLog, sessionID := exchangeAuthcodeForTokens(t,
 				test.authcodeExchange, testidplister.NewUpstreamIDPListerBuilder().BuildFederationDomainIdentityProvidersListerFinder(), test.kubeResources)
 			var parsedAuthcodeExchangeResponseBody map[string]any
 			require.NoError(t, json.Unmarshal(rsp.Body.Bytes(), &parsedAuthcodeExchangeResponseBody))
@@ -1741,7 +1781,7 @@ func TestTokenEndpointTokenExchange(t *testing.T) { // tests for grant_type "urn
 
 			// Perform the token exchange.
 			approxRequestTime := time.Now()
-			log.Reset()
+			actualAuditLog.Reset() // Clear audit logs from the authcode exchange
 			subject.ServeHTTP(rsp, req)
 			t.Logf("response: %#v", rsp)
 			t.Logf("response body: %q", rsp.Body.String())
@@ -1750,7 +1790,7 @@ func TestTokenEndpointTokenExchange(t *testing.T) { // tests for grant_type "urn
 			testutil.RequireEqualContentType(t, rsp.Header().Get("Content-Type"), "application/json")
 
 			if test.wantAuditLogs != nil {
-				testutil.CompareAuditLogs(t, test.wantAuditLogs(sessionID), log.String())
+				testutil.CompareAuditLogs(t, test.wantAuditLogs(sessionID), actualAuditLog.String())
 			}
 
 			var parsedResponseBody map[string]any
@@ -2104,17 +2144,14 @@ func TestRefreshGrant(t *testing.T) {
 		if expectToValidateToken != nil {
 			want.wantUpstreamOIDCValidateTokenCall = happyUpstreamValidateTokenCall(expectToValidateToken, true)
 		}
-		want.wantAuditLogs = func(sessionID string) []testutil.WantedAuditLog {
-			return []testutil.WantedAuditLog{
-				testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
-					"sessionID": sessionID,
-					"params":    "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
-				}),
-			}
-		}
 		return want
 	}
 
+	refreshResponseWithAuditLogs := func(expectedValues tokenEndpointResponseExpectedValues, wantAuditLogs func(sessionID string) []testutil.WantedAuditLog) tokenEndpointResponseExpectedValues {
+		expectedValues.wantAuditLogs = wantAuditLogs
+		return expectedValues
+	}
+
 	happyRefreshTokenResponseForOpenIDAndOfflineAccessWithUsernameAndGroups := func(wantCustomSessionDataStored *psession.CustomSessionData, expectToValidateToken *oauth2.Token, wantDownstreamUsername string, wantDownstreamGroups []string) tokenEndpointResponseExpectedValues {
 		// Should always have some custom session data stored. The other expectations happens to be the
 		// same as the same values as the authcode exchange case.
@@ -2259,9 +2296,39 @@ func TestRefreshGrant(t *testing.T) {
 				}).WithRefreshedTokens(refreshedUpstreamTokensWithIDAndRefreshTokens()).Build()),
 			authcodeExchange: happyAuthcodeExchangeInputsForOIDCUpstream,
 			refreshRequest: refreshRequestInputs{
-				want: happyRefreshTokenResponseForOpenIDAndOfflineAccess(
-					upstreamOIDCCustomSessionDataWithNewRefreshToken(oidcUpstreamRefreshedRefreshToken),
-					refreshedUpstreamTokensWithIDAndRefreshTokens(),
+				want: refreshResponseWithAuditLogs(
+					happyRefreshTokenResponseForOpenIDAndOfflineAccess(
+						upstreamOIDCCustomSessionDataWithNewRefreshToken(oidcUpstreamRefreshedRefreshToken),
+						refreshedUpstreamTokensWithIDAndRefreshTokens(),
+					),
+					func(sessionID string) []testutil.WantedAuditLog {
+						return []testutil.WantedAuditLog{
+							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
+								"params": func() string {
+									params := url.Values{}
+									params.Set("client_id", "pinniped-cli")
+									params.Set("grant_type", "refresh_token")
+									params.Set("refresh_token", "redacted")
+									params.Set("scope", "openid")
+									return params.Encode()
+								}(),
+							}),
+							testutil.WantAuditLog("Identity Refreshed From Upstream IDP", map[string]any{
+								"sessionID":        sessionID,
+								"upstreamGroups":   []any{},
+								"upstreamUsername": "some-username",
+							}),
+							testutil.WantAuditLog("Session Refreshed", map[string]any{
+								"sessionID": sessionID,
+								"username":  "some-username",
+								"groups": []any{
+									"group1",
+									"groups2",
+								},
+								"subject": "https://issuer?sub=some-subject",
+							}),
+						}
+					},
 				),
 			},
 		},
@@ -2432,8 +2499,23 @@ func TestRefreshGrant(t *testing.T) {
 					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
 						return []testutil.WantedAuditLog{
 							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
+								"params": func() string {
+									params := url.Values{}
+									params.Set("client_id", "pinniped-cli")
+									params.Set("grant_type", "refresh_token")
+									params.Set("refresh_token", "redacted")
+									params.Set("scope", "openid")
+									return params.Encode()
+								}(),
+							}),
+							testutil.WantAuditLog("Identity Refreshed From Upstream IDP", map[string]any{
+								"sessionID":        sessionID,
+								"upstreamGroups":   []any{},
+								"upstreamUsername": "some-username",
+							}),
+							testutil.WantAuditLog("Authentication Rejected By Transforms", map[string]any{
 								"sessionID": sessionID,
-								"params":    "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+								"reason":    "Upstream refresh rejected by configured identity policy: authentication was rejected by a configured policy.",
 							}),
 						}
 					},
@@ -2487,8 +2569,7 @@ func TestRefreshGrant(t *testing.T) {
 					wantAuditLogs: func(sessionID string) []testutil.WantedAuditLog {
 						return []testutil.WantedAuditLog{
 							testutil.WantAuditLog("HTTP Request Parameters", map[string]any{
-								"sessionID": sessionID,
-								"params":    "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
+								"params": "client_id=pinniped-cli&code=redacted&code_verifier=redacted&grant_type=authorization_code&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback",
 							}),
 						}
 					},
@@ -4790,7 +4871,7 @@ func TestRefreshGrant(t *testing.T) {
 			// First exchange the authcode for tokens, including a refresh token.
 			// It's actually fine to use this function even when simulating LDAP (which uses a different flow) because it's
 			// just populating a secret in storage.
-			subject, rsp, authCode, jwtSigningKey, secrets, oauthStore, _, _ := exchangeAuthcodeForTokens(t,
+			subject, rsp, authCode, jwtSigningKey, secrets, oauthStore, actualAuditLog, sessionID := exchangeAuthcodeForTokens(t,
 				test.authcodeExchange, test.idps.BuildFederationDomainIdentityProvidersListerFinder(), test.kubeResources)
 			var parsedAuthcodeExchangeResponseBody map[string]any
 			require.NoError(t, json.Unmarshal(rsp.Body.Bytes(), &parsedAuthcodeExchangeResponseBody))
@@ -4823,12 +4904,17 @@ func TestRefreshGrant(t *testing.T) {
 				test.refreshRequest.modifyTokenRequest(req, firstRefreshToken, parsedAuthcodeExchangeResponseBody["access_token"].(string))
 			}
 
+			actualAuditLog.Reset() // Clear audit logs from the authcode exchange
 			refreshResponse := httptest.NewRecorder()
 			approxRequestTime := time.Now()
 			subject.ServeHTTP(refreshResponse, req)
 			t.Logf("second response: %#v", refreshResponse)
 			t.Logf("second response body: %q", refreshResponse.Body.String())
 
+			if test.refreshRequest.want.wantAuditLogs != nil {
+				testutil.CompareAuditLogs(t, test.refreshRequest.want.wantAuditLogs(sessionID), actualAuditLog.String())
+			}
+
 			// Test that we did or did not make a call to the upstream provider's interface to perform refresh.
 			switch {
 			case test.refreshRequest.want.wantOIDCUpstreamRefreshCall != nil:
@@ -4964,7 +5050,7 @@ func exchangeAuthcodeForTokens(
 	jwtSigningKey *ecdsa.PrivateKey,
 	secrets v1.SecretInterface,
 	oauthStore *storage.KubeStorage,
-	log *bytes.Buffer,
+	actualAuditLog *bytes.Buffer,
 	sessionID string,
 ) {
 	authRequest := deepCopyRequestForm(happyAuthRequest)
@@ -4991,11 +5077,11 @@ func exchangeAuthcodeForTokens(
 		test.makeJwksSigningKeyAndProvider = generateJWTSigningKeyAndJWKSProvider
 	}
 
+	logger, actualAuditLog := plog.TestLogger(t)
+
 	var oauthHelper fosite.OAuth2Provider
 	// Note that makeHappyOauthHelper() calls simulateAuthEndpointHavingAlreadyRun() to preload the session storage.
-	oauthHelper, authCode, jwtSigningKey = makeHappyOauthHelper(t, authRequest, oauthStore, test.makeJwksSigningKeyAndProvider, test.customSessionData, test.modifySession)
-
-	logger, log := plog.TestLogger(t)
+	oauthHelper, authCode, jwtSigningKey = makeHappyOauthHelper(t, authRequest, oauthStore, test.makeJwksSigningKeyAndProvider, test.customSessionData, test.modifySession, logger)
 
 	subject = NewHandler(
 		idps,
@@ -5029,17 +5115,10 @@ func exchangeAuthcodeForTokens(
 	t.Logf("response: %#v", rsp)
 	t.Logf("response body: %q", rsp.Body.String())
 
+	sessionID = getSessionID(t, secrets)
+
 	if test.want.wantAuditLogs != nil {
-		authCodeLabelSelector := fmt.Sprintf("%s=%s", crud.SecretLabelKey, authorizationcode.TypeLabelValue)
-		allAuthCodeSecrets, _ := secrets.List(context.Background(), metav1.ListOptions{
-			LabelSelector: authCodeLabelSelector,
-		})
-		require.NotNil(t, allAuthCodeSecrets)
-		require.Len(t, allAuthCodeSecrets.Items, 1, "expected exactly one secret with label %s", authCodeLabelSelector)
-		session, err := authorizationcode.ReadFromSecret(&allAuthCodeSecrets.Items[0])
-		require.NoError(t, err)
-		sessionID = session.Request.GetID()
-		testutil.CompareAuditLogs(t, test.want.wantAuditLogs(sessionID), log.String())
+		testutil.CompareAuditLogs(t, test.want.wantAuditLogs(sessionID), actualAuditLog.String())
 	}
 
 	wantNonceValueInIDToken := true // ID tokens returned by the authcode exchange must include the nonce from the auth request (unlike refreshed ID tokens)
@@ -5056,7 +5135,21 @@ func exchangeAuthcodeForTokens(
 		approxRequestTime,
 	)
 
-	return subject, rsp, authCode, jwtSigningKey, secrets, oauthStore, log, sessionID
+	return subject, rsp, authCode, jwtSigningKey, secrets, oauthStore, actualAuditLog, sessionID
+}
+
+func getSessionID(t *testing.T, secrets v1.SecretInterface) string {
+	t.Helper()
+
+	authCodeLabelSelector := fmt.Sprintf("%s=%s", crud.SecretLabelKey, authorizationcode.TypeLabelValue)
+	allAuthCodeSecrets, _ := secrets.List(context.Background(), metav1.ListOptions{
+		LabelSelector: authCodeLabelSelector,
+	})
+	require.NotNil(t, allAuthCodeSecrets)
+	require.Len(t, allAuthCodeSecrets.Items, 1, "expected exactly one secret with label %s", authCodeLabelSelector)
+	session, err := authorizationcode.ReadFromSecret(&allAuthCodeSecrets.Items[0])
+	require.NoError(t, err)
+	return session.Request.GetID()
 }
 
 func requireTokenEndpointBehavior(
@@ -5207,11 +5300,12 @@ func makeHappyOauthHelper(
 	makeJwksSigningKeyAndProvider MakeJwksSigningKeyAndProviderFunc,
 	initialCustomSessionData *psession.CustomSessionData,
 	modifySession func(session *psession.PinnipedSession),
+	auditLogger plog.AuditLogger,
 ) (fosite.OAuth2Provider, string, *ecdsa.PrivateKey) {
 	t.Helper()
 
 	jwtSigningKey, jwkProvider := makeJwksSigningKeyAndProvider(t, goodIssuer)
-	oauthHelper := oidc.FositeOauth2Helper(store, goodIssuer, hmacSecretFunc, jwkProvider, oidc.DefaultOIDCTimeoutsConfiguration())
+	oauthHelper := oidc.FositeOauth2Helper(store, goodIssuer, hmacSecretFunc, jwkProvider, oidc.DefaultOIDCTimeoutsConfiguration(), auditLogger)
 	authResponder := simulateAuthEndpointHavingAlreadyRun(t, authRequest, oauthHelper, initialCustomSessionData, modifySession)
 	return oauthHelper, authResponder.GetCode(), jwtSigningKey
 }

internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go

@@ -0,0 +1,59 @@
+// Copyright 2020-2024 the Pinniped contributors. All Rights Reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+package tokenendpointauditor
+
+import (
+	"context"
+
+	"github.com/ory/fosite"
+	"github.com/ory/fosite/compose"
+	"k8s.io/apimachinery/pkg/util/sets"
+
+	"go.pinniped.dev/internal/plog"
+)
+
+type parameterAuditorHandler struct {
+	auditLogger plog.AuditLogger
+}
+
+func AuditorHandlerFactory(auditLogger plog.AuditLogger) compose.Factory {
+	return func(_ fosite.Configurator, _ any, _ any) any {
+		return &parameterAuditorHandler{
+			auditLogger: auditLogger,
+		}
+	}
+}
+
+var _ fosite.TokenEndpointHandler = (*parameterAuditorHandler)(nil)
+
+func (p parameterAuditorHandler) PopulateTokenEndpointResponse(_ context.Context, _ fosite.AccessRequester, _ fosite.AccessResponder) error {
+	return nil
+}
+
+func (p parameterAuditorHandler) HandleTokenEndpointRequest(_ context.Context, _ fosite.AccessRequester) error {
+	return nil
+}
+
+func (p parameterAuditorHandler) CanSkipClientAuth(_ context.Context, _ fosite.AccessRequester) bool {
+	return false
+}
+
+func paramsSafeToLogTokenEndpoint() sets.Set[string] {
+	return sets.New(
+		// Standard params from https://openid.net/specs/openid-connect-core-1_0.html for authcode and refresh grants.
+		// Redacting code, client_secret, refresh_token, and PKCE code_verifier params.
+		"grant_type", "client_id", "redirect_uri", "scope",
+		// Token exchange params from https://datatracker.ietf.org/doc/html/rfc8693.
+		// Redact subject_token and actor_token.
+		// We don't allow all of these, but they should be safe to log.
+		"audience", "resource", "scope", "requested_token_type", "actor_token_type", "subject_token_type",
+	)
+}
+
+func (p parameterAuditorHandler) CanHandleTokenEndpointRequest(ctx context.Context, requester fosite.AccessRequester) bool {
+	p.auditLogger.Audit(plog.AuditEventHTTPRequestParameters, ctx, plog.NoSessionPersisted(),
+		"params", plog.SanitizeParams(requester.GetRequestForm(), paramsSafeToLogTokenEndpoint()))
+
+	return false
+}

internal/federationdomain/endpointsmanager/manager.go

@@ -119,6 +119,7 @@ func (m *Manager) SetFederationDomains(federationDomains ...*federationdomainpro
 			tokenHMACKeyGetter,
 			nil,
 			timeoutsConfiguration,
+			m.auditLogger,
 		)
 
 		// For all the other endpoints, make another oauth helper with exactly the same settings except use real storage.
@@ -128,6 +129,7 @@ func (m *Manager) SetFederationDomains(federationDomains ...*federationdomainpro
 			tokenHMACKeyGetter,
 			m.dynamicJWKSProvider,
 			timeoutsConfiguration,
+			m.auditLogger,
 		)
 
 		upstreamStateEncoder := dynamiccodec.New(

internal/federationdomain/oidc/oidc.go

@@ -22,6 +22,7 @@ import (
 	"go.pinniped.dev/internal/federationdomain/clientregistry"
 	"go.pinniped.dev/internal/federationdomain/csrftoken"
 	"go.pinniped.dev/internal/federationdomain/endpoints/jwks"
+	"go.pinniped.dev/internal/federationdomain/endpoints/tokenendpointauditor"
 	"go.pinniped.dev/internal/federationdomain/endpoints/tokenexchange"
 	"go.pinniped.dev/internal/federationdomain/formposthtml"
 	"go.pinniped.dev/internal/federationdomain/idtokenlifespan"
@@ -231,6 +232,7 @@ func FositeOauth2Helper(
 	hmacSecretOfLengthAtLeast32Func func() []byte,
 	jwksProvider jwks.DynamicJWKSProvider,
 	timeoutsConfiguration timeouts.Configuration,
+	auditLogger plog.AuditLogger,
 ) fosite.OAuth2Provider {
 	oauthConfig := &fosite.Config{
 		IDTokenIssuer: issuer,
@@ -271,6 +273,8 @@ func FositeOauth2Helper(
 			CoreStrategy:               strategy.NewDynamicOauth2HMACStrategy(oauthConfig, hmacSecretOfLengthAtLeast32Func),
 			OpenIDConnectTokenStrategy: strategy.NewDynamicOpenIDConnectECDSAStrategy(oauthConfig, jwksProvider),
 		},
+		// Put this before others to make sure it logs params!
+		tokenendpointauditor.AuditorHandlerFactory(auditLogger),
 		compose.OAuth2AuthorizeExplicitFactory,
 		compose.OAuth2RefreshTokenGrantFactory,
 		// Use a custom factory to allow selective overrides of the ID token lifespan during authcode exchange.

internal/testutil/log_lines.go

@@ -68,10 +68,13 @@ func CompareAuditLogs(t *testing.T, wantAuditLogs []WantedAuditLog, actualAuditL
 	wantMessages := make([]string, 0)
 	for _, wantAuditLog := range wantAuditLogs {
 		wantJsonAuditLog := make(map[string]any)
+		require.Empty(t, wantAuditLog.Params["level"], "do not specify level in audit log expectations")
 		wantJsonAuditLog["level"] = "info"
+		require.Empty(t, wantAuditLog.Params["message"], "do not specify message in audit log expectations")
 		wantJsonAuditLog["message"] = wantAuditLog.Message
 		wantMessages = append(wantMessages, wantAuditLog.Message)
 		wantJsonAuditLog["auditEvent"] = true
+		require.Empty(t, wantAuditLog.Params["timestamp"], "do not specify timestamp in audit log expectations")
 		wantJsonAuditLog["timestamp"] = "2099-08-08T13:57:36.123456Z"
 		for k, v := range wantAuditLog.Params {
 			wantJsonAuditLog[k] = v
@@ -82,7 +85,8 @@ func CompareAuditLogs(t *testing.T, wantAuditLogs []WantedAuditLog, actualAuditL
 	actualJsonAuditLogs := make([]map[string]any, 0)
 	actualMessages := make([]string, 0)
 	actualAuditLogs := strings.Split(actualAuditLogsOneLiner, "\n")
-	require.GreaterOrEqual(t, len(actualAuditLogs), 2)
+	require.GreaterOrEqual(t, len(actualAuditLogs), 2,
+		"expected %d log lines, found %d", len(wantAuditLogs), len(actualAuditLogs)-1)
 	actualAuditLogs = actualAuditLogs[:len(actualAuditLogs)-1] // trim off the last ""
 	for _, actualAuditLog := range actualAuditLogs {
 		actualJsonAuditLog := make(map[string]any)