diff --git a/internal/federationdomain/downstreamsession/downstream_session.go b/internal/federationdomain/downstreamsession/downstream_session.go index 5097a6adf..96d7cce11 100644 --- a/internal/federationdomain/downstreamsession/downstream_session.go +++ b/internal/federationdomain/downstreamsession/downstream_session.go @@ -49,14 +49,18 @@ func NewPinnipedSession( ) (*psession.PinnipedSession, error) { now := time.Now().UTC() - auditLogger.Audit(plog.AuditEventIdentityFromUpstreamIDP, ctx, c.SessionIDGetter, + // Do not associate this audit event with a session ID, since the session has not yet "started", + // and this session may not be persisted to permanent storage. + auditLogger.Audit(plog.AuditEventIdentityFromUpstreamIDP, ctx, nil, "upstreamUsername", c.UpstreamIdentity.UpstreamUsername, "upstreamGroups", c.UpstreamIdentity.UpstreamGroups) downstreamUsername, downstreamGroups, err := applyIdentityTransformations(ctx, c.IdentityProvider.GetTransforms(), c.UpstreamIdentity.UpstreamUsername, c.UpstreamIdentity.UpstreamGroups) if err != nil { - auditLogger.Audit(plog.AuditEventAuthenticationRejectedByTransforms, ctx, c.SessionIDGetter, + // Do not associate this audit event with a session ID, since we reject this session (and + // will never write it to permanent storage). + auditLogger.Audit(plog.AuditEventAuthenticationRejectedByTransforms, ctx, nil, "err", err) return nil, err } diff --git a/internal/federationdomain/endpoints/auth/auth_handler_test.go b/internal/federationdomain/endpoints/auth/auth_handler_test.go index 515c6d64e..651ac22d7 100644 --- a/internal/federationdomain/endpoints/auth/auth_handler_test.go +++ b/internal/federationdomain/endpoints/auth/auth_handler_test.go @@ -37,6 +37,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/storage" "go.pinniped.dev/internal/here" "go.pinniped.dev/internal/plog" @@ -692,7 +693,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantBodyStringWithLocationInHref bool wantLocationHeader string wantUpstreamStateParamInLocationHeader bool - wantAuditLogs func(encodedStateParam string) []string + wantAuditLogs func(encodedStateParam, sessionID string) []string // Assertions for when an authcode should be returned, i.e. the request was authenticated by an // upstream LDAP provider or an upstream OIDC password grant flow. @@ -729,12 +730,12 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantLocationHeader: expectedRedirectLocationForUpstreamOIDC(expectedUpstreamStateParam(nil, "", oidcUpstreamName, "oidc"), nil), wantUpstreamStateParamInLocationHeader: true, wantBodyStringWithLocationInHref: true, - wantAuditLogs: func(encodedStateParam string) []string { + wantAuditLogs: func(encodedStateParam, sessionID string) []string { return []string{ - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-oidc-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditEvent":true,"displayName":"some-oidc-idp","resourceName":"some-oidc-idp","resourceUID":"oidc-resource-uid","type":"oidc"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-oidc-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-oidc-idp","resourceName":"some-oidc-idp","resourceUID":"oidc-resource-uid","type":"oidc"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditID":"some-audit-id","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, } }, }, @@ -755,12 +756,12 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantLocationHeader: expectedRedirectLocationForUpstreamOIDC(expectedUpstreamStateParam(map[string]string{"client_id": dynamicClientID, "scope": testutil.AllDynamicClientScopesSpaceSep}, "", oidcUpstreamName, "oidc"), nil), wantUpstreamStateParamInLocationHeader: true, wantBodyStringWithLocationInHref: true, - wantAuditLogs: func(encodedStateParam string) []string { + wantAuditLogs: func(encodedStateParam, sessionID string) []string { return []string{ - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditEvent":true,"params":"client_id=` + dynamicClientID + `&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-oidc-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+offline_access+pinniped%3Arequest-audience+username+groups&state=redacted"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditEvent":true,"displayName":"some-oidc-idp","resourceName":"some-oidc-idp","resourceUID":"oidc-resource-uid","type":"oidc"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=` + dynamicClientID + `&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-oidc-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+offline_access+pinniped%3Arequest-audience+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-oidc-idp","resourceName":"some-oidc-idp","resourceUID":"oidc-resource-uid","type":"oidc"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditID":"some-audit-id","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, } }, }, @@ -780,12 +781,12 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantLocationHeader: expectedRedirectLocationForUpstreamGithub(expectedUpstreamStateParam(nil, "", githubUpstreamName, "github")), wantUpstreamStateParamInLocationHeader: true, wantBodyStringWithLocationInHref: true, - wantAuditLogs: func(encodedStateParam string) []string { + wantAuditLogs: func(encodedStateParam, sessionID string) []string { return []string{ - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-github-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditEvent":true,"displayName":"some-github-idp","resourceName":"some-github-idp","resourceUID":"github-resource-uid","type":"github"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-github-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-github-idp","resourceName":"some-github-idp","resourceUID":"github-resource-uid","type":"github"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditID":"some-audit-id","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, } }, }, @@ -806,12 +807,12 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantLocationHeader: expectedRedirectLocationForUpstreamGithub(expectedUpstreamStateParam(map[string]string{"client_id": dynamicClientID, "scope": testutil.AllDynamicClientScopesSpaceSep}, "", githubUpstreamName, "github")), wantUpstreamStateParamInLocationHeader: true, wantBodyStringWithLocationInHref: true, - wantAuditLogs: func(encodedStateParam string) []string { + wantAuditLogs: func(encodedStateParam, sessionID string) []string { return []string{ - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditEvent":true,"params":"client_id=` + dynamicClientID + `&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-github-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+offline_access+pinniped%3Arequest-audience+username+groups&state=redacted"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditEvent":true,"displayName":"some-github-idp","resourceName":"some-github-idp","resourceUID":"github-resource-uid","type":"github"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=` + dynamicClientID + `&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-github-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+offline_access+pinniped%3Arequest-audience+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-github-idp","resourceName":"some-github-idp","resourceUID":"github-resource-uid","type":"github"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditID":"some-audit-id","auditEvent":true,"authorizeID":"` + generateAuthorizeId(encodedStateParam) + `"}`, } }, }, @@ -981,6 +982,15 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantDownstreamPKCEChallenge: downstreamPKCEChallenge, wantDownstreamPKCEChallengeMethod: downstreamPKCEChallengeMethod, wantDownstreamCustomSessionData: expectedHappyOIDCPasswordGrantCustomSession, + wantAuditLogs: func(encodedStateParam, sessionID string) []string { + return []string{ + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":true,"Pinniped-Password":true}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-password-granting-oidc-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-password-granting-oidc-idp","resourceName":"some-password-granting-oidc-idp","resourceUID":"some-password-granting-resource-uid","type":"oidc"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Identity From Upstream IDP","auditID":"some-audit-id","auditEvent":true,"upstreamUsername":"test-oidc-pinniped-username","upstreamGroups":["test-pinniped-group-0","test-pinniped-group-1"]}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Session Started","sessionID":"` + sessionID + `","auditID":"some-audit-id","auditEvent":true,"username":"test-oidc-pinniped-username","groups":["test-pinniped-group-0","test-pinniped-group-1"],"subject":"https://my-upstream-issuer.com?idpName=some-password-granting-oidc-idp&sub=abc123-some+guid","additionalClaims":{},"warnings":[]}`, + } + }, }, { name: "OIDC upstream password grant happy path using GET with identity transformations which change username and groups", @@ -1023,6 +1033,15 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantContentType: jsonContentType, wantLocationHeader: urlWithQuery(downstreamRedirectURI, fositeAccessDeniedWithConfiguredPolicyRejectionHintErrorQuery), wantBodyString: "", + wantAuditLogs: func(encodedStateParam, sessionID string) []string { + return []string{ + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":true,"Pinniped-Password":true}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-password-granting-oidc-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-password-granting-oidc-idp","resourceName":"some-password-granting-oidc-idp","resourceUID":"some-password-granting-resource-uid","type":"oidc"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Identity From Upstream IDP","auditID":"some-audit-id","auditEvent":true,"upstreamUsername":"test-oidc-pinniped-username","upstreamGroups":["test-pinniped-group-0","test-pinniped-group-1"]}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Authentication Rejected By Transforms","auditID":"some-audit-id","auditEvent":true,"err":"configured identity policy rejected this authentication: authentication was rejected by a configured policy"}`, + } + }, }, { name: "OIDC upstream password grant happy path using GET with additional claim mappings", @@ -1087,7 +1106,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantDownstreamAdditionalClaims: nil, // downstream claims are empty }, { - name: "LDAP cli upstream happy path using GET", + name: "LDAP upstream cli_password flow happy path using GET", idps: testidplister.NewUpstreamIDPListerBuilder().WithLDAP(upstreamLDAPIdentityProviderBuilder().Build()), method: http.MethodGet, path: happyGetRequestPathForLDAPUpstream, @@ -1106,11 +1125,13 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantDownstreamPKCEChallenge: downstreamPKCEChallenge, wantDownstreamPKCEChallengeMethod: downstreamPKCEChallengeMethod, wantDownstreamCustomSessionData: expectedHappyLDAPUpstreamCustomSession, - wantAuditLogs: func(encodedStateParam string) []string { + wantAuditLogs: func(encodedStateParam, sessionID string) []string { return []string{ - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditEvent":true,"Pinniped-Username":true,"Pinniped-Password":true}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-ldap-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditEvent":true,"displayName":"some-ldap-idp","resourceName":"some-ldap-idp","resourceUID":"ldap-resource-uid","type":"ldap"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":true,"Pinniped-Password":true}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-ldap-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-ldap-idp","resourceName":"some-ldap-idp","resourceUID":"ldap-resource-uid","type":"ldap"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Identity From Upstream IDP","auditID":"some-audit-id","auditEvent":true,"upstreamUsername":"some-mapped-ldap-username","upstreamGroups":["group1","group2","group3"]}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Session Started","sessionID":"` + sessionID + `","auditID":"some-audit-id","auditEvent":true,"username":"some-mapped-ldap-username","groups":["group1","group2","group3"],"subject":"ldaps://some-ldap-host:123?base=ou%3Dusers%2Cdc%3Dpinniped%2Cdc%3Ddev&idpName=some-ldap-idp&sub=some-ldap-uid","additionalClaims":null,"warnings":[]}`, } }, }, @@ -1140,11 +1161,13 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo happyLDAPUsernameFromAuthenticator, happyLDAPGroups, ), - wantAuditLogs: func(encodedStateParam string) []string { + wantAuditLogs: func(encodedStateParam, sessionID string) []string { return []string{ - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditEvent":true,"Pinniped-Username":true,"Pinniped-Password":true}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-ldap-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, - `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditEvent":true,"displayName":"some-ldap-idp","resourceName":"some-ldap-idp","resourceUID":"ldap-resource-uid","type":"ldap"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":true,"Pinniped-Password":true}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-ldap-idp&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-ldap-idp","resourceName":"some-ldap-idp","resourceUID":"ldap-resource-uid","type":"ldap"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Identity From Upstream IDP","auditID":"some-audit-id","auditEvent":true,"upstreamUsername":"some-mapped-ldap-username","upstreamGroups":["group1","group2","group3"]}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"downstreamsession/downstream_session.go:$downstreamsession.NewPinnipedSession","message":"Session Started","sessionID":"` + sessionID + `","auditID":"some-audit-id","auditEvent":true,"username":"username_prefix:some-mapped-ldap-username","groups":["groups_prefix:group1","groups_prefix:group2","groups_prefix:group3"],"subject":"ldaps://some-ldap-host:123?base=ou%3Dusers%2Cdc%3Dpinniped%2Cdc%3Ddev&idpName=some-ldap-idp&sub=some-ldap-uid","additionalClaims":null,"warnings":[]}`, } }, }, @@ -1486,6 +1509,14 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo wantContentType: jsonContentType, wantLocationHeader: urlWithQuery(downstreamRedirectURI, fositeLoginRequiredErrorQuery), wantBodyString: "", + wantAuditLogs: func(encodedStateParam, sessionID string) []string { + return []string{ + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Custom Headers Used","auditID":"some-audit-id","auditEvent":true,"Pinniped-Username":false,"Pinniped-Password":false}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"HTTP Request Parameters","auditID":"some-audit-id","auditEvent":true,"params":"client_id=pinniped-cli&code_challenge=redacted&code_challenge_method=S256&nonce=redacted&pinniped_idp_name=some-oidc-idp&prompt=none&redirect_uri=http%3A%2F%2F127.0.0.1%2Fcallback&response_type=code&scope=openid+profile+email+username+groups&state=redacted"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).ServeHTTP","message":"Using Upstream IDP","auditID":"some-audit-id","auditEvent":true,"displayName":"some-oidc-idp","resourceName":"some-oidc-idp","resourceUID":"oidc-resource-uid","type":"oidc"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"auth/auth_handler.go:$auth.(*authorizeHandler).authorize","message":"Upstream Authorize Redirect","auditID":"some-audit-id","auditEvent":true,"authorizeID":""}`, + } + }, }, { name: "OIDC upstream browser flow with error while decoding CSRF cookie just generates a new cookie and succeeds as usual", @@ -3561,6 +3592,10 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo req.Header.Set("Pinniped-Password", *test.customPasswordHeader) } rsp := httptest.NewRecorder() + + req, _ = requestlogger.NewRequestWithAuditID(req, func() string { + return "some-audit-id" + }) subject.ServeHTTP(rsp, req) t.Logf("response: %#v", rsp) t.Logf("response body: %q", rsp.Body.String()) @@ -3572,7 +3607,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo testutil.RequireSecurityHeadersWithFormPostPageCSPs(t, rsp) if test.wantPasswordGrantCall != nil { - test.wantPasswordGrantCall.args.Ctx = reqContext + test.wantPasswordGrantCall.args.Ctx = req.Context() test.idps.RequireExactlyOneCallToPasswordCredentialsGrantAndValidateTokens(t, test.wantPasswordGrantCall.performedByUpstreamName, test.wantPasswordGrantCall.args, ) @@ -3581,16 +3616,14 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo } actualLocation := rsp.Header().Get("Location") + actualQueryStateParam := "" + sessionID := "" switch { case test.wantLocationHeader != "": if test.wantUpstreamStateParamInLocationHeader { - actualQueryStateParam := requireEqualDecodedStateParams(t, actualLocation, test.wantLocationHeader, test.stateEncoder) + actualQueryStateParam = requireEqualDecodedStateParams(t, actualLocation, test.wantLocationHeader, test.stateEncoder) // Ignore the state, since it was encoded with a randomly-generated initialization vector that cannot be reproduced. requireEqualURLsIgnoringState(t, actualLocation, test.wantLocationHeader) - if test.wantAuditLogs != nil { - wantAuditLogs := test.wantAuditLogs(actualQueryStateParam) - testutil.RequireLogLines(t, wantAuditLogs, auditLog) - } } else { require.Equal(t, test.wantLocationHeader, actualLocation) } @@ -3606,7 +3639,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo test.wantDownstreamClientID = pinnipedCLIClientID // default assertion value when not provided by test case } require.Len(t, rsp.Header().Values("Location"), 1) - oidctestutil.RequireAuthCodeRegexpMatch( + sessionID = oidctestutil.RequireAuthCodeRegexpMatch( t, rsp.Header().Get("Location"), test.wantRedirectLocationRegexp, @@ -3630,6 +3663,11 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo require.Empty(t, rsp.Header().Values("Location")) } + if test.wantAuditLogs != nil { + wantAuditLogs := test.wantAuditLogs(actualQueryStateParam, sessionID) + testutil.RequireLogLines(t, wantAuditLogs, auditLog) + } + switch { case test.wantBodyJSON != "": require.JSONEq(t, test.wantBodyJSON, rsp.Body.String()) diff --git a/internal/federationdomain/endpoints/callback/callback_handler_test.go b/internal/federationdomain/endpoints/callback/callback_handler_test.go index 12e6d65e9..366929aaf 100644 --- a/internal/federationdomain/endpoints/callback/callback_handler_test.go +++ b/internal/federationdomain/endpoints/callback/callback_handler_test.go @@ -1806,7 +1806,7 @@ func TestCallbackEndpoint(t *testing.T) { // Else if we want a body that contains a regex-matched auth code, assert that (for "response_mode=form_post"). case test.wantBodyFormResponseRegexp != "": - oidctestutil.RequireAuthCodeRegexpMatch( + _ = oidctestutil.RequireAuthCodeRegexpMatch( t, rsp.Body.String(), test.wantBodyFormResponseRegexp, @@ -1834,7 +1834,7 @@ func TestCallbackEndpoint(t *testing.T) { if test.wantRedirectLocationRegexp != "" { require.Len(t, rsp.Header().Values("Location"), 1) - oidctestutil.RequireAuthCodeRegexpMatch( + _ = oidctestutil.RequireAuthCodeRegexpMatch( t, rsp.Header().Get("Location"), test.wantRedirectLocationRegexp, diff --git a/internal/federationdomain/endpoints/login/post_login_handler_test.go b/internal/federationdomain/endpoints/login/post_login_handler_test.go index 003d3f02e..24591b9a5 100644 --- a/internal/federationdomain/endpoints/login/post_login_handler_test.go +++ b/internal/federationdomain/endpoints/login/post_login_handler_test.go @@ -1168,7 +1168,7 @@ func TestPostLoginEndpoint(t *testing.T) { // Expecting a success redirect to the client. require.Equal(t, tt.wantBodyString, rsp.Body.String()) require.Len(t, rsp.Header().Values("Location"), 1) - oidctestutil.RequireAuthCodeRegexpMatch( + _ = oidctestutil.RequireAuthCodeRegexpMatch( t, actualLocation, tt.wantRedirectLocationRegexp, @@ -1204,7 +1204,7 @@ func TestPostLoginEndpoint(t *testing.T) { // Expecting the body of the response to be a html page with a form (for "response_mode=form_post"). _, hasLocationHeader := rsp.Header()["Location"] require.False(t, hasLocationHeader) - oidctestutil.RequireAuthCodeRegexpMatch( + _ = oidctestutil.RequireAuthCodeRegexpMatch( t, rsp.Body.String(), tt.wantBodyFormResponseRegexp, diff --git a/internal/federationdomain/endpointsmanager/manager.go b/internal/federationdomain/endpointsmanager/manager.go index f3104a494..0512d1b3e 100644 --- a/internal/federationdomain/endpointsmanager/manager.go +++ b/internal/federationdomain/endpointsmanager/manager.go @@ -8,6 +8,7 @@ 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" @@ -190,9 +191,14 @@ func (m *Manager) SetFederationDomains(federationDomains ...*federationdomainpro } func (m *Manager) buildHandlerChain(nextHandler http.Handler) { - handler := m.buildManagerHandler(nextHandler) // build the basic handler for FederationDomain endpoints - handler = requestlogger.WithHTTPRequestAuditLogging(handler, m.auditLogger) // log all requests, including audit ID - handler = requestlogger.WithAuditID(handler) // add random audit ID to request context and response headers + // build the basic handler for FederationDomain endpoints + handler := m.buildManagerHandler(nextHandler) + // log all requests, including audit ID + handler = requestlogger.WithHTTPRequestAuditLogging(handler, m.auditLogger) + // add random audit ID to request context and response headers + handler = requestlogger.WithAuditID(handler, func() string { + return uuid.New().String() + }) m.handlerChain = handler } diff --git a/internal/federationdomain/requestlogger/request_logger.go b/internal/federationdomain/requestlogger/request_logger.go index 6f9dc03ed..7657cebbd 100644 --- a/internal/federationdomain/requestlogger/request_logger.go +++ b/internal/federationdomain/requestlogger/request_logger.go @@ -9,7 +9,6 @@ import ( "net/http" "time" - "github.com/google/uuid" "k8s.io/apimachinery/pkg/types" apisaudit "k8s.io/apiserver/pkg/apis/audit" "k8s.io/apiserver/pkg/audit" @@ -19,19 +18,19 @@ import ( "go.pinniped.dev/internal/plog" ) -func WithAuditID(handler http.Handler) http.Handler { - return withAuditID(handler, func() string { - return uuid.New().String() - }) +func NewRequestWithAuditID(r *http.Request, newAuditIDFunc func() string) (*http.Request, string) { + ctx := audit.WithAuditContext(r.Context()) + r = r.WithContext(ctx) + + auditID := newAuditIDFunc() + audit.WithAuditID(ctx, types.UID(auditID)) + + return r, auditID } -func withAuditID(handler http.Handler, newAuditIDFunc func() string) http.Handler { +func WithAuditID(handler http.Handler, newAuditIDFunc func() string) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - ctx := audit.WithAuditContext(r.Context()) - r = r.WithContext(ctx) - - auditID := newAuditIDFunc() - audit.WithAuditID(ctx, types.UID(auditID)) + r, auditID := NewRequestWithAuditID(r, newAuditIDFunc) // Send the Audit-ID response header. w.Header().Set(apisaudit.HeaderAuditID, auditID) diff --git a/internal/plog/audit_event.go b/internal/plog/audit_event.go index 727e031c3..bc0774521 100644 --- a/internal/plog/audit_event.go +++ b/internal/plog/audit_event.go @@ -21,7 +21,7 @@ const ( AuditEventIdentityRefreshedFromUpstreamIDP AuditEventMessage = "Identity Refreshed From Upstream IDP" AuditEventSessionStarted AuditEventMessage = "Session Started" AuditEventSessionRefreshed AuditEventMessage = "Session Refreshed" - AuditEventAuthenticationRejectedByTransforms AuditEventMessage = "Authentication RejectedBy Transforms" + AuditEventAuthenticationRejectedByTransforms AuditEventMessage = "Authentication Rejected By Transforms" AuditEventUpstreamOIDCTokenRevoked AuditEventMessage = "Upstream OIDC Token Revoked" //nolint:gosec // this is not a credential AuditEventSessionGarbageCollected AuditEventMessage = "Session Garbage Collected" AuditEventTokenCredentialRequest AuditEventMessage = "TokenCredentialRequest" //nolint:gosec // this is not a credential diff --git a/internal/testutil/oidctestutil/session_storage_assertions.go b/internal/testutil/oidctestutil/session_storage_assertions.go index 0d5f896b0..143aac071 100644 --- a/internal/testutil/oidctestutil/session_storage_assertions.go +++ b/internal/testutil/oidctestutil/session_storage_assertions.go @@ -47,7 +47,7 @@ func RequireAuthCodeRegexpMatch( wantDownstreamRedirectURI string, wantCustomSessionData *psession.CustomSessionData, wantDownstreamAdditionalClaims map[string]any, -) { +) string { t.Helper() // Assert that Location header matches regular expression. @@ -73,7 +73,7 @@ func RequireAuthCodeRegexpMatch( // One authcode should have been stored. testutil.RequireNumberOfSecretsMatchingLabelSelector(t, secretsClient, labels.Set{crud.SecretLabelKey: authorizationcode.TypeLabelValue}, 1) - storedRequestFromAuthcode, storedSessionFromAuthcode := validateAuthcodeStorage( + sessionID, storedRequestFromAuthcode, storedSessionFromAuthcode := validateAuthcodeStorage( t, oauthStore, authcodeDataAndSignature[1], // Authcode store key is authcode signature @@ -114,6 +114,8 @@ func RequireAuthCodeRegexpMatch( wantDownstreamNonce, ) } + + return sessionID } func includesOpenIDScope(scopes []string) bool { @@ -139,7 +141,7 @@ func validateAuthcodeStorage( wantDownstreamRedirectURI string, wantCustomSessionData *psession.CustomSessionData, wantDownstreamAdditionalClaims map[string]any, -) (*fosite.Request, *psession.PinnipedSession) { +) (string, *fosite.Request, *psession.PinnipedSession) { t.Helper() const ( @@ -151,6 +153,8 @@ func validateAuthcodeStorage( storedAuthorizeRequestFromAuthcode, err := oauthStore.GetAuthorizeCodeSession(context.Background(), storeKey, nil) require.NoError(t, err) + sessionID := storedAuthorizeRequestFromAuthcode.GetID() + // Check that storage returned the expected concrete data types. storedRequestFromAuthcode, storedSessionFromAuthcode := castStoredAuthorizeRequest(t, storedAuthorizeRequestFromAuthcode) @@ -258,7 +262,7 @@ func validateAuthcodeStorage( // Check that the custom Pinniped session data matches. require.Equal(t, wantCustomSessionData, storedSessionFromAuthcode.Custom) - return storedRequestFromAuthcode, storedSessionFromAuthcode + return sessionID, storedRequestFromAuthcode, storedSessionFromAuthcode } func validatePKCEStorage(