diff --git a/internal/federationdomain/endpoints/auth/auth_handler_test.go b/internal/federationdomain/endpoints/auth/auth_handler_test.go index c71cefb62..bcf2db9ba 100644 --- a/internal/federationdomain/endpoints/auth/auth_handler_test.go +++ b/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") diff --git a/internal/federationdomain/endpoints/callback/callback_handler_test.go b/internal/federationdomain/endpoints/callback/callback_handler_test.go index 01bcb8fd3..583fdc02f 100644 --- a/internal/federationdomain/endpoints/callback/callback_handler_test.go +++ b/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) diff --git a/internal/federationdomain/endpoints/login/post_login_handler_test.go b/internal/federationdomain/endpoints/login/post_login_handler_test.go index 24591b9a5..3a0545533 100644 --- a/internal/federationdomain/endpoints/login/post_login_handler_test.go +++ b/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") diff --git a/internal/federationdomain/endpoints/token/token_handler.go b/internal/federationdomain/endpoints/token/token_handler.go index 8f6dfd5ef..e50811748 100644 --- a/internal/federationdomain/endpoints/token/token_handler.go +++ b/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( diff --git a/internal/federationdomain/endpoints/token/token_handler_test.go b/internal/federationdomain/endpoints/token/token_handler_test.go index 0d32b92d6..40ae7c6e0 100644 --- a/internal/federationdomain/endpoints/token/token_handler_test.go +++ b/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 } diff --git a/internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go b/internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go new file mode 100644 index 000000000..d55e2b35e --- /dev/null +++ b/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 ¶meterAuditorHandler{ + 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 +} diff --git a/internal/federationdomain/endpointsmanager/manager.go b/internal/federationdomain/endpointsmanager/manager.go index b3a0a60ee..5d0d943cd 100644 --- a/internal/federationdomain/endpointsmanager/manager.go +++ b/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( diff --git a/internal/federationdomain/oidc/oidc.go b/internal/federationdomain/oidc/oidc.go index db187acfc..77a9b3a28 100644 --- a/internal/federationdomain/oidc/oidc.go +++ b/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. diff --git a/internal/testutil/log_lines.go b/internal/testutil/log_lines.go index 048e7c916..da776f201 100644 --- a/internal/testutil/log_lines.go +++ b/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)