audit logging WIP

internal/controller/supervisorstorage/garbage_collector.go

@@ -9,6 +9,7 @@ import (
 	"fmt"
 	"time"
 
+	"github.com/ory/fosite"
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/labels"
@@ -35,10 +36,12 @@ import (
 const minimumRepeatInterval = 30 * time.Second
 
 type garbageCollectorController struct {
-	idpCache              UpstreamOIDCIdentityProviderICache
-	secretInformer        corev1informers.SecretInformer
-	kubeClient            kubernetes.Interface
-	clock                 clock.Clock
+	idpCache       UpstreamOIDCIdentityProviderICache
+	secretInformer corev1informers.SecretInformer
+	kubeClient     kubernetes.Interface
+	clock          clock.Clock
+	auditLogger    plog.AuditLogger
+
 	timeOfMostRecentSweep time.Time
 }
 
@@ -53,6 +56,7 @@ func GarbageCollectorController(
 	kubeClient kubernetes.Interface,
 	secretInformer corev1informers.SecretInformer,
 	withInformer pinnipedcontroller.WithInformerOptionFunc,
+	auditLogger plog.AuditLogger,
 ) controllerlib.Controller {
 	isSecretWithGCAnnotation := func(obj metav1.Object) bool {
 		secret, ok := obj.(*corev1.Secret)
@@ -70,6 +74,7 @@ func GarbageCollectorController(
 				secretInformer: secretInformer,
 				kubeClient:     kubeClient,
 				clock:          clock,
+				auditLogger:    auditLogger,
 			},
 		},
 		withInformer(
@@ -163,6 +168,7 @@ func (c *garbageCollectorController) Sync(ctx controllerlib.Context) error {
 			plog.WarningErr("failed to garbage collect resource", err, logKV(secret)...)
 			continue
 		}
+		c.maybeAuditLogGC(storageType, secret)
 		plog.Info("storage garbage collector deleted resource", logKV(secret)...)
 	}
 
@@ -192,7 +198,10 @@ func (c *garbageCollectorController) maybeRevokeUpstreamOIDCToken(ctx context.Co
 			return nil
 		}
 		// When the downstream authcode was never used, then its storage must contain the latest upstream token.
-		return c.tryRevokeUpstreamOIDCToken(ctx, authorizeCodeSession.Request.Session.(*psession.PinnipedSession).Custom, secret)
+		return c.tryRevokeUpstreamOIDCToken(ctx,
+			authorizeCodeSession.Request.Session.(*psession.PinnipedSession).Custom,
+			authorizeCodeSession.Request,
+			secret)
 
 	case accesstoken.TypeLabelValue:
 		// For access token storage, check if the "offline_access" scope was granted on the downstream session.
@@ -203,11 +212,13 @@ func (c *garbageCollectorController) maybeRevokeUpstreamOIDCToken(ctx context.Co
 		if err != nil {
 			return err
 		}
-		pinnipedSession := accessTokenSession.Request.Session.(*psession.PinnipedSession)
 		if accessTokenSession.Request.GetGrantedScopes().Has(oidcapi.ScopeOfflineAccess) {
 			return nil
 		}
-		return c.tryRevokeUpstreamOIDCToken(ctx, pinnipedSession.Custom, secret)
+		return c.tryRevokeUpstreamOIDCToken(ctx,
+			accessTokenSession.Request.Session.(*psession.PinnipedSession).Custom,
+			accessTokenSession.Request,
+			secret)
 
 	case refreshtoken.TypeLabelValue:
 		// For refresh token storage, always revoke its upstream token. This refresh token storage could be
@@ -217,7 +228,10 @@ func (c *garbageCollectorController) maybeRevokeUpstreamOIDCToken(ctx context.Co
 		if err != nil {
 			return err
 		}
-		return c.tryRevokeUpstreamOIDCToken(ctx, refreshTokenSession.Request.Session.(*psession.PinnipedSession).Custom, secret)
+		return c.tryRevokeUpstreamOIDCToken(ctx,
+			refreshTokenSession.Request.Session.(*psession.PinnipedSession).Custom,
+			refreshTokenSession.Request,
+			secret)
 
 	case pkce.TypeLabelValue:
 		// For PKCE storage, its very existence means that the downstream authcode was never exchanged, because
@@ -237,7 +251,12 @@ func (c *garbageCollectorController) maybeRevokeUpstreamOIDCToken(ctx context.Co
 	}
 }
 
-func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken(ctx context.Context, customSessionData *psession.CustomSessionData, secret *corev1.Secret) error {
+func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken(
+	ctx context.Context,
+	customSessionData *psession.CustomSessionData,
+	request *fosite.Request,
+	secret *corev1.Secret,
+) error {
 	// When session was for another upstream IDP type, e.g. LDAP, there is no upstream OIDC token involved.
 	if customSessionData.ProviderType != psession.ProviderTypeOIDC {
 		return nil
@@ -264,6 +283,8 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken(ctx context.Cont
 		if err != nil {
 			return err
 		}
+		c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, nil, request,
+			"type", upstreamprovider.RefreshTokenType)
 		plog.Trace("garbage collector successfully revoked upstream OIDC refresh token (or provider has no revocation endpoint)", logKV(secret)...)
 	}
 
@@ -272,12 +293,56 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken(ctx context.Cont
 		if err != nil {
 			return err
 		}
+		c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, nil, request,
+			"type", upstreamprovider.AccessTokenType)
 		plog.Trace("garbage collector successfully revoked upstream OIDC access token (or provider has no revocation endpoint)", logKV(secret)...)
 	}
 
 	return nil
 }
 
+func (c *garbageCollectorController) maybeAuditLogGC(storageType string, secret *corev1.Secret) {
+	r, err := c.requestFromSecret(storageType, secret)
+	if err == nil && r != nil {
+		c.auditLogger.Audit(plog.AuditEventSessionGarbageCollected, nil, r, "storageType", storageType)
+	}
+}
+
+func (c *garbageCollectorController) requestFromSecret(storageType string, secret *corev1.Secret) (*fosite.Request, error) {
+	switch storageType {
+	case authorizationcode.TypeLabelValue:
+		authorizeCodeSession, err := authorizationcode.ReadFromSecret(secret)
+		if err != nil {
+			return nil, err
+		}
+		return authorizeCodeSession.Request, nil
+
+	case accesstoken.TypeLabelValue:
+		accessTokenSession, err := accesstoken.ReadFromSecret(secret)
+		if err != nil {
+			return nil, err
+		}
+		return accessTokenSession.Request, nil
+
+	case refreshtoken.TypeLabelValue:
+		refreshTokenSession, err := refreshtoken.ReadFromSecret(secret)
+		if err != nil {
+			return nil, err
+		}
+		return refreshTokenSession.Request, nil
+
+	case pkce.TypeLabelValue:
+		return nil, nil // if this still exists, then it means that the user never exchanged their authcode
+
+	case openidconnect.TypeLabelValue:
+		return nil, nil // if this still exists, then it means that the user never exchanged their authcode
+
+	default:
+		// There are no other storage types, so this should never happen in practice.
+		return nil, errors.New("garbage collector saw invalid label on Secret when trying to determine session ID")
+	}
+}
+
 func logKV(secret *corev1.Secret) []any {
 	return []any{
 		"secretName", secret.Name,

internal/controller/supervisorstorage/garbage_collector_test.go

@@ -31,6 +31,7 @@ import (
 	"go.pinniped.dev/internal/fositestorage/accesstoken"
 	"go.pinniped.dev/internal/fositestorage/authorizationcode"
 	"go.pinniped.dev/internal/fositestorage/refreshtoken"
+	"go.pinniped.dev/internal/plog"
 	"go.pinniped.dev/internal/psession"
 	"go.pinniped.dev/internal/testutil"
 	"go.pinniped.dev/internal/testutil/oidctestutil"
@@ -55,6 +56,7 @@ func TestGarbageCollectorControllerInformerFilters(t *testing.T) {
 				nil,
 				secretsInformer,
 				observableWithInformerOption.WithInformer, // make it possible to observe the behavior of the Filters
+				plog.New(),
 			)
 			secretsInformerFilter = observableWithInformerOption.GetFilterForInformer(secretsInformer)
 		})
@@ -148,6 +150,7 @@ func TestGarbageCollectorControllerSync(t *testing.T) {
 				kubeClient,
 				kubeInformers.Core().V1().Secrets(),
 				controllerlib.WithInformer,
+				plog.New(),
 			)
 
 			// Set this at the last second to support calling subject.Name().

internal/federationdomain/downstreamsession/downstream_session.go

@@ -34,33 +34,43 @@ type SessionConfig struct {
 	ClientID string
 	// The scopes that were granted for the new downstream session.
 	GrantedScopes []string
+	// The identity provider used to authenticate the user.
+	IdentityProvider resolvedprovider.FederationDomainResolvedIdentityProvider
+	// The fosite Requester that is starting this session.
+	SessionIDGetter plog.SessionIDGetter
 }
 
 // NewPinnipedSession applies the configured FederationDomain identity transformations
 // and creates a downstream Pinniped session.
 func NewPinnipedSession(
 	ctx context.Context,
-	idp resolvedprovider.FederationDomainResolvedIdentityProvider,
+	auditLogger plog.AuditLogger,
 	c *SessionConfig,
 ) (*psession.PinnipedSession, error) {
 	now := time.Now().UTC()
 
+	auditLogger.Audit(plog.AuditEventIdentityFromUpstreamIDP, ctx, c.SessionIDGetter,
+		"upstreamUsername", c.UpstreamIdentity.UpstreamUsername,
+		"upstreamGroups", c.UpstreamIdentity.UpstreamGroups)
+
 	downstreamUsername, downstreamGroups, err := applyIdentityTransformations(ctx,
-		idp.GetTransforms(), c.UpstreamIdentity.UpstreamUsername, c.UpstreamIdentity.UpstreamGroups)
+		c.IdentityProvider.GetTransforms(), c.UpstreamIdentity.UpstreamUsername, c.UpstreamIdentity.UpstreamGroups)
 	if err != nil {
+		auditLogger.Audit(plog.AuditEventAuthenticationRejectedByTransforms, ctx, c.SessionIDGetter,
+			"err", err)
 		return nil, err
 	}
 
 	customSessionData := &psession.CustomSessionData{
 		Username:         downstreamUsername,
 		UpstreamUsername: c.UpstreamIdentity.UpstreamUsername,
 		UpstreamGroups:   c.UpstreamIdentity.UpstreamGroups,
-		ProviderUID:      idp.GetProvider().GetResourceUID(),
-		ProviderName:     idp.GetProvider().GetResourceName(),
-		ProviderType:     idp.GetSessionProviderType(),
+		ProviderUID:      c.IdentityProvider.GetProvider().GetResourceUID(),
+		ProviderName:     c.IdentityProvider.GetProvider().GetResourceName(),
+		ProviderType:     c.IdentityProvider.GetSessionProviderType(),
 		Warnings:         c.UpstreamLoginExtras.Warnings,
 	}
-	idp.ApplyIDPSpecificSessionDataToSession(customSessionData, c.UpstreamIdentity.IDPSpecificSessionData)
+	c.IdentityProvider.ApplyIDPSpecificSessionDataToSession(customSessionData, c.UpstreamIdentity.IDPSpecificSessionData)
 
 	pinnipedSession := &psession.PinnipedSession{
 		Fosite: &openid.DefaultSession{
@@ -94,6 +104,13 @@ func NewPinnipedSession(
 
 	pinnipedSession.IDTokenClaims().Extra = extras
 
+	auditLogger.Audit(plog.AuditEventSessionStarted, ctx, c.SessionIDGetter,
+		"username", downstreamUsername,
+		"groups", downstreamGroups,
+		"subject", c.UpstreamIdentity.DownstreamSubject,
+		"additionalClaims", c.UpstreamLoginExtras.DownstreamAdditionalClaims,
+		"warnings", c.UpstreamLoginExtras.Warnings)
+
 	return pinnipedSession, nil
 }
 

internal/federationdomain/endpoints/auth/auth_handler.go

@@ -13,6 +13,7 @@ import (
 	"github.com/ory/fosite"
 	"github.com/ory/fosite/handler/openid"
 	fositejwt "github.com/ory/fosite/token/jwt"
+	"k8s.io/apimachinery/pkg/util/sets"
 
 	oidcapi "go.pinniped.dev/generated/latest/apis/supervisor/oidc"
 	"go.pinniped.dev/internal/federationdomain/csrftoken"
@@ -34,6 +35,21 @@ const (
 	promptParamNone = "none"
 )
 
+//nolint:gochecknoglobals // please treat this as a readonly const, do not mutate
+var paramsSafeToLog = sets.New[string](
+	// Standard params from https://openid.net/specs/openid-connect-core-1_0.html, some of which are ignored.
+	// Redacting state and nonce params, in case they contain any info that the client considers sensitive.
+	"scope", "response_type", "client_id", "redirect_uri", "response_mode", "display", "prompt",
+	"max_age", "ui_locales", "id_token_hint", "login_hint", "acr_values", "claims_locales", "claims",
+	"request", "request_uri", "registration",
+	// PKCE params from https://datatracker.ietf.org/doc/html/rfc7636. Let code_challenge be redacted.
+	"code_challenge_method",
+	// Custom Pinniped authorization params.
+	oidcapi.AuthorizeUpstreamIDPNameParamName, oidcapi.AuthorizeUpstreamIDPTypeParamName,
+	// Google-specific param that some client libraries will send anyway. Ignored by Pinniped but safe to log.
+	"access_type",
+)
+
 type authorizeHandler struct {
 	downstreamIssuerURL       string
 	idpFinder                 federationdomainproviders.FederationDomainIdentityProvidersFinderI
@@ -44,6 +60,7 @@ type authorizeHandler struct {
 	generateNonce             func() (nonce.Nonce, error)
 	upstreamStateEncoder      oidc.Encoder
 	cookieCodec               oidc.Codec
+	auditLogger               plog.AuditLogger
 }
 
 func NewHandler(
@@ -56,6 +73,7 @@ func NewHandler(
 	generateNonce func() (nonce.Nonce, error),
 	upstreamStateEncoder oidc.Encoder,
 	cookieCodec oidc.Codec,
+	auditLogger plog.AuditLogger,
 ) http.Handler {
 	h := &authorizeHandler{
 		downstreamIssuerURL:       downstreamIssuerURL,
@@ -67,6 +85,7 @@ func NewHandler(
 		generateNonce:             generateNonce,
 		upstreamStateEncoder:      upstreamStateEncoder,
 		cookieCodec:               cookieCodec,
+		auditLogger:               auditLogger,
 	}
 	// During a response_mode=form_post auth request using the browser flow, the custom form_post html page may
 	// be used to post certain errors back to the CLI from this handler's response, so allow the form_post
@@ -83,9 +102,10 @@ func (h *authorizeHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	// The client set a username or password header, so they are trying to log in without using a browser.
-	requestedBrowserlessFlow := len(r.Header.Values(oidcapi.AuthorizeUsernameHeaderName)) > 0 ||
-		len(r.Header.Values(oidcapi.AuthorizePasswordHeaderName)) > 0
+	// If the client set a username or password header, they are trying to log in without using a browser.
+	hadUsernameHeader := len(r.Header.Values(oidcapi.AuthorizeUsernameHeaderName)) > 0
+	hadPasswordHeader := len(r.Header.Values(oidcapi.AuthorizePasswordHeaderName)) > 0
+	requestedBrowserlessFlow := hadUsernameHeader || hadPasswordHeader
 
 	// Need to parse the request params, so we can get the IDP name. The style and text of the error is inspired by
 	// fosite's implementation of NewAuthorizeRequest(). Fosite only calls ParseMultipartForm() there. However,
@@ -112,6 +132,15 @@ func (h *authorizeHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	// Log if these headers were present, but don't log the actual values. The password is obviously sensitive,
+	// and sometimes users use their password as their username by mistake.
+	h.auditLogger.Audit(plog.AuditEventHTTPRequestCustomHeadersUsed, r.Context(), nil,
+		oidcapi.AuthorizeUsernameHeaderName, hadUsernameHeader,
+		oidcapi.AuthorizePasswordHeaderName, hadPasswordHeader)
+
+	h.auditLogger.Audit(plog.AuditEventHTTPRequestParameters, r.Context(), nil,
+		"params", plog.SanitizeParams(r.Form, paramsSafeToLog))
+
 	// Note that the client might have used oidcapi.AuthorizeUpstreamIDPNameParamName and
 	// oidcapi.AuthorizeUpstreamIDPTypeParamName query (or form) params to request a certain upstream IDP.
 	// The Pinniped CLI has been sending these params since v0.9.0.
@@ -141,6 +170,12 @@ func (h *authorizeHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	h.auditLogger.Audit(plog.AuditEventUsingUpstreamIDP, r.Context(), nil,
+		"displayName", idp.GetDisplayName(),
+		"resourceName", idp.GetProvider().GetResourceName(),
+		"resourceUID", idp.GetProvider().GetResourceUID(),
+		"type", idp.GetSessionProviderType())
+
 	h.authorize(w, r, requestedBrowserlessFlow, idpNameQueryParamValue, idp)
 }
 
@@ -206,11 +241,13 @@ func (h *authorizeHandler) authorizeWithoutBrowser(
 		return err
 	}
 
-	session, err := downstreamsession.NewPinnipedSession(r.Context(), idp, &downstreamsession.SessionConfig{
+	session, err := downstreamsession.NewPinnipedSession(r.Context(), h.auditLogger, &downstreamsession.SessionConfig{
 		UpstreamIdentity:    identity,
 		UpstreamLoginExtras: loginExtras,
 		ClientID:            authorizeRequester.GetClient().GetID(),
 		GrantedScopes:       authorizeRequester.GetGrantedScopes(),
+		IdentityProvider:    idp,
+		SessionIDGetter:     authorizeRequester,
 	})
 	if err != nil {
 		return fosite.ErrAccessDenied.WithHintf("Reason: %s.", err.Error())

internal/federationdomain/endpoints/auth/auth_handler_test.go

@@ -36,6 +36,7 @@ import (
 	"go.pinniped.dev/internal/federationdomain/oidcclientvalidator"
 	"go.pinniped.dev/internal/federationdomain/storage"
 	"go.pinniped.dev/internal/here"
+	"go.pinniped.dev/internal/plog"
 	"go.pinniped.dev/internal/psession"
 	"go.pinniped.dev/internal/testutil"
 	"go.pinniped.dev/internal/testutil/oidctestutil"
@@ -3624,6 +3625,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo
 				oauthHelperWithNullStorage, oauthHelperWithRealStorage,
 				test.generateCSRF, test.generatePKCE, test.generateNonce,
 				test.stateEncoder, test.cookieEncoder,
+				plog.New(),
 			)
 			runOneTestCase(t, test, subject, kubeOauthStore, supervisorClient, kubeClient, secretsClient)
 		})
@@ -3647,6 +3649,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo
 			oauthHelperWithNullStorage, oauthHelperWithRealStorage,
 			test.generateCSRF, test.generatePKCE, test.generateNonce,
 			test.stateEncoder, test.cookieEncoder,
+			plog.New(),
 		)
 
 		runOneTestCase(t, test, subject, kubeOauthStore, supervisorClient, kubeClient, secretsClient)