From e21e1326b711e74a77146c56ebe1deecac8fb83b Mon Sep 17 00:00:00 2001 From: Ryan Richard Date: Tue, 12 Nov 2024 14:08:36 -0800 Subject: [PATCH] tokencredentialrequest audit logs successful responses Co-authored-by: Joshua Casey --- internal/concierge/apiserver/apiserver.go | 9 +- internal/registry/credentialrequest/rest.go | 6 +- .../registry/credentialrequest/rest_test.go | 122 +++++++++++++----- 3 files changed, 101 insertions(+), 36 deletions(-) diff --git a/internal/concierge/apiserver/apiserver.go b/internal/concierge/apiserver/apiserver.go index a147efb8e..b58a4b2c2 100644 --- a/internal/concierge/apiserver/apiserver.go +++ b/internal/concierge/apiserver/apiserver.go @@ -15,6 +15,7 @@ import ( "k8s.io/apiserver/pkg/registry/rest" genericapiserver "k8s.io/apiserver/pkg/server" utilversion "k8s.io/apiserver/pkg/util/version" + "k8s.io/utils/clock" "go.pinniped.dev/internal/clientcertissuer" "go.pinniped.dev/internal/controllerinit" @@ -83,7 +84,13 @@ func (c completedConfig) New() (*PinnipedServer, error) { for _, f := range []func() (schema.GroupVersionResource, rest.Storage){ func() (schema.GroupVersionResource, rest.Storage) { tokenCredReqGVR := c.ExtraConfig.LoginConciergeGroupVersion.WithResource("tokencredentialrequests") - tokenCredStorage := credentialrequest.NewREST(c.ExtraConfig.Authenticator, c.ExtraConfig.Issuer, tokenCredReqGVR.GroupResource(), c.ExtraConfig.AuditLogger) + tokenCredStorage := credentialrequest.NewREST( + c.ExtraConfig.Authenticator, + c.ExtraConfig.Issuer, + tokenCredReqGVR.GroupResource(), + c.ExtraConfig.AuditLogger, + clock.RealClock{}, + ) return tokenCredReqGVR, tokenCredStorage }, func() (schema.GroupVersionResource, rest.Storage) { diff --git a/internal/registry/credentialrequest/rest.go b/internal/registry/credentialrequest/rest.go index 29b411c60..623915088 100644 --- a/internal/registry/credentialrequest/rest.go +++ b/internal/registry/credentialrequest/rest.go @@ -18,6 +18,7 @@ import ( "k8s.io/apiserver/pkg/authentication/user" genericapirequest "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/apiserver/pkg/registry/rest" + "k8s.io/utils/clock" "k8s.io/utils/trace" loginapi "go.pinniped.dev/generated/latest/apis/concierge/login" @@ -38,12 +39,14 @@ func NewREST( issuer clientcertissuer.ClientCertIssuer, resource schema.GroupResource, auditLogger plog.AuditLogger, + clock clock.Clock, ) *REST { return &REST{ authenticator: authenticator, issuer: issuer, tableConvertor: rest.NewDefaultTableConvertor(resource), auditLogger: auditLogger, + clock: clock, } } @@ -52,6 +55,7 @@ type REST struct { issuer clientcertissuer.ClientCertIssuer tableConvertor rest.TableConvertor auditLogger plog.AuditLogger + clock clock.Clock } // Assert that our *REST implements all the optional interfaces that we expect it to implement. @@ -123,7 +127,7 @@ func (r *REST) Create(ctx context.Context, obj runtime.Object, createValidation } // this timestamp should be returned from IssueClientCertPEM but this is a safe approximation - expires := metav1.NewTime(time.Now().UTC().Add(clientCertificateTTL)) + expires := metav1.NewTime(r.clock.Now().UTC().Add(clientCertificateTTL)) certPEM, keyPEM, err := r.issuer.IssueClientCertPEM(userInfo.GetName(), userInfo.GetGroups(), clientCertificateTTL) if err != nil { traceFailureWithError(t, "cert issuer", err) diff --git a/internal/registry/credentialrequest/rest_test.go b/internal/registry/credentialrequest/rest_test.go index c1c8e5e10..0d091c7fd 100644 --- a/internal/registry/credentialrequest/rest_test.go +++ b/internal/registry/credentialrequest/rest_test.go @@ -4,6 +4,7 @@ package credentialrequest import ( + "bytes" "context" "errors" "fmt" @@ -18,10 +19,13 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/runtime/schema" + "k8s.io/apiserver/pkg/audit" "k8s.io/apiserver/pkg/authentication/user" genericapirequest "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/apiserver/pkg/registry/rest" "k8s.io/klog/v2" + "k8s.io/utils/clock" + clocktesting "k8s.io/utils/clock/testing" "k8s.io/utils/ptr" loginapi "go.pinniped.dev/generated/latest/apis/concierge/login" @@ -33,7 +37,7 @@ import ( ) func TestNew(t *testing.T) { - r := NewREST(nil, nil, schema.GroupResource{Group: "bears", Resource: "panda"}, nil) + r := NewREST(nil, nil, schema.GroupResource{Group: "bears", Resource: "panda"}, nil, clock.RealClock{}) require.NotNil(t, r) require.False(t, r.NamespaceScoped()) require.Equal(t, []string{"pinniped"}, r.Categories()) @@ -71,6 +75,10 @@ func TestCreate(t *testing.T) { var logger *testutil.TranscriptLogger var originalKLogLevel klog.Level var auditLogger plog.AuditLogger + var actualAuditLog *bytes.Buffer + var frozenNow time.Time + var frozenClock *clocktesting.FakeClock + var wantAuditLog []testutil.WantedAuditLog it.Before(func() { r = require.New(t) @@ -80,10 +88,13 @@ func TestCreate(t *testing.T) { originalKLogLevel = testutil.GetGlobalKlogLevel() // trace.Log() utility will only log at level 2 or above, so set that for this test. testutil.SetGlobalKlogLevel(t, 2) //nolint:staticcheck // old test of code using trace.Log() - auditLogger, _ = plog.TestAuditLogger(t) + auditLogger, actualAuditLog = plog.TestAuditLogger(t) + frozenNow = time.Date(2024, time.September, 12, 4, 25, 56, 778899, time.UTC) + frozenClock = clocktesting.NewFakeClock(frozenNow) }) it.After(func() { + testutil.CompareAuditLogs(t, wantAuditLog, actualAuditLog.String()) klog.ClearLogger() testutil.SetGlobalKlogLevel(t, originalKLogLevel) //nolint:staticcheck // old test of code using trace.Log() ctrl.Finish() @@ -106,28 +117,36 @@ func TestCreate(t *testing.T) { 5*time.Minute, ).Return([]byte("test-cert"), []byte("test-key"), nil) - storage := NewREST(requestAuthenticator, clientCertIssuer, schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, clientCertIssuer, schema.GroupResource{}, auditLogger, frozenClock) - response, err := callCreate(context.Background(), storage, req) + response, err := callCreate(storage, req) r.NoError(err) r.IsType(&loginapi.TokenCredentialRequest{}, response) - expires := response.(*loginapi.TokenCredentialRequest).Status.Credential.ExpirationTimestamp - r.NotNil(expires) - r.InDelta(time.Now().Add(5*time.Minute).Unix(), expires.Unix(), 5) - response.(*loginapi.TokenCredentialRequest).Status.Credential.ExpirationTimestamp = metav1.Time{} - r.Equal(response, &loginapi.TokenCredentialRequest{ Status: loginapi.TokenCredentialRequestStatus{ Credential: &loginapi.ClusterCredential{ - ExpirationTimestamp: metav1.Time{}, + ExpirationTimestamp: metav1.NewTime(frozenNow.Add(5 * time.Minute).UTC()), ClientCertificateData: "test-cert", ClientKeyData: "test-key", }, }, }) + requireOneLogStatement(r, logger, `"success" userID:,hasExtra:false,authenticated:true`) + + wantAuditLog = []testutil.WantedAuditLog{ + testutil.WantAuditLog("TokenCredentialRequest", map[string]any{ + "auditID": "fake-audit-id", + "authenticated": true, + "expires": "2024-09-12T04:30:56Z", // this is frozenNow + 5 minutes in UTC + "personalInfo": map[string]any{ + "username": "test-user", + "groups": []any{"test-group-1", "test-group-2"}, + }, + }), + } }) it("CreateFailsWithValidTokenWhenCertIssuerFails", func() { @@ -145,9 +164,9 @@ func TestCreate(t *testing.T) { IssueClientCertPEM(gomock.Any(), gomock.Any(), gomock.Any()). Return(nil, nil, fmt.Errorf("some certificate authority error")) - storage := NewREST(requestAuthenticator, clientCertIssuer, schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, clientCertIssuer, schema.GroupResource{}, auditLogger, frozenClock) - response, err := callCreate(context.Background(), storage, req) + response, err := callCreate(storage, req) requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) requireOneLogStatement(r, logger, `"failure" failureType:cert issuer,msg:some certificate authority error`) }) @@ -158,9 +177,9 @@ func TestCreate(t *testing.T) { requestAuthenticator := mockcredentialrequest.NewMockTokenCredentialRequestAuthenticator(ctrl) requestAuthenticator.EXPECT().AuthenticateTokenCredentialRequest(gomock.Any(), req).Return(nil, nil) - storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger, frozenClock) - response, err := callCreate(context.Background(), storage, req) + response, err := callCreate(storage, req) requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) requireOneLogStatement(r, logger, `"success" userID:,hasExtra:false,authenticated:false`) @@ -173,9 +192,9 @@ func TestCreate(t *testing.T) { requestAuthenticator.EXPECT().AuthenticateTokenCredentialRequest(gomock.Any(), req). Return(nil, errors.New("some webhook error")) - storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger, frozenClock) - response, err := callCreate(context.Background(), storage, req) + response, err := callCreate(storage, req) requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) requireOneLogStatement(r, logger, `"failure" failureType:token authentication,msg:some webhook error`) @@ -188,9 +207,9 @@ func TestCreate(t *testing.T) { requestAuthenticator.EXPECT().AuthenticateTokenCredentialRequest(gomock.Any(), req). Return(&user.DefaultInfo{Name: ""}, nil) - storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger, frozenClock) - response, err := callCreate(context.Background(), storage, req) + response, err := callCreate(storage, req) requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) requireOneLogStatement(r, logger, `"success" userID:,hasExtra:false,authenticated:false`) @@ -207,9 +226,9 @@ func TestCreate(t *testing.T) { Groups: []string{"test-group-1", "test-group-2"}, }, nil) - storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger, frozenClock) - response, err := callCreate(context.Background(), storage, req) + response, err := callCreate(storage, req) requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) requireOneLogStatement(r, logger, `"success" userID:test-uid,hasExtra:false,authenticated:false`) @@ -226,9 +245,9 @@ func TestCreate(t *testing.T) { Extra: map[string][]string{"test-key": {"test-val-1", "test-val-2"}}, }, nil) - storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, nil, schema.GroupResource{}, auditLogger, frozenClock) - response, err := callCreate(context.Background(), storage, req) + response, err := callCreate(storage, req) requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) requireOneLogStatement(r, logger, `"success" userID:,hasExtra:true,authenticated:false`) @@ -236,7 +255,7 @@ func TestCreate(t *testing.T) { it("CreateFailsWhenGivenTheWrongInputType", func() { notACredentialRequest := runtime.Unknown{} - response, err := NewREST(nil, nil, schema.GroupResource{}, auditLogger).Create( + response, err := NewREST(nil, nil, schema.GroupResource{}, auditLogger, frozenClock).Create( genericapirequest.NewContext(), ¬ACredentialRequest, rest.ValidateAllObjectFunc, @@ -247,8 +266,8 @@ func TestCreate(t *testing.T) { }) it("CreateFailsWhenTokenValueIsEmptyInRequest", func() { - storage := NewREST(nil, nil, schema.GroupResource{}, auditLogger) - response, err := callCreate(context.Background(), storage, credentialRequest(loginapi.TokenCredentialRequestSpec{ + storage := NewREST(nil, nil, schema.GroupResource{}, auditLogger, frozenClock) + response, err := callCreate(storage, credentialRequest(loginapi.TokenCredentialRequestSpec{ Token: "", })) @@ -258,7 +277,7 @@ func TestCreate(t *testing.T) { }) it("CreateFailsWhenValidationFails", func() { - storage := NewREST(nil, nil, schema.GroupResource{}, auditLogger) + storage := NewREST(nil, nil, schema.GroupResource{}, auditLogger, frozenClock) response, err := storage.Create( context.Background(), validCredentialRequest(), @@ -278,9 +297,12 @@ func TestCreate(t *testing.T) { requestAuthenticator.EXPECT().AuthenticateTokenCredentialRequest(gomock.Any(), req.DeepCopy()). Return(&user.DefaultInfo{Name: "test-user"}, nil) - storage := NewREST(requestAuthenticator, successfulIssuer(ctrl), schema.GroupResource{}, auditLogger) + fakeReqContext := audit.WithAuditContext(context.Background()) + audit.WithAuditID(fakeReqContext, "fake-audit-id") + + storage := NewREST(requestAuthenticator, successfulIssuer(ctrl), schema.GroupResource{}, auditLogger, frozenClock) response, err := storage.Create( - context.Background(), + fakeReqContext, req, func(ctx context.Context, obj runtime.Object) error { credentialRequest, _ := obj.(*loginapi.TokenCredentialRequest) @@ -290,6 +312,18 @@ func TestCreate(t *testing.T) { &metav1.CreateOptions{}) r.NoError(err) r.NotEmpty(response) + + wantAuditLog = []testutil.WantedAuditLog{ + testutil.WantAuditLog("TokenCredentialRequest", map[string]any{ + "auditID": "fake-audit-id", + "authenticated": true, + "expires": "2024-09-12T04:30:56Z", // this is frozenNow + 5 minutes in UTC + "personalInfo": map[string]any{ + "username": "test-user", + "groups": []any{}, + }, + }), + } }) it("CreateDoesNotAllowValidationFunctionToSeeTheActualRequestToken", func() { @@ -299,11 +333,16 @@ func TestCreate(t *testing.T) { requestAuthenticator.EXPECT().AuthenticateTokenCredentialRequest(gomock.Any(), req.DeepCopy()). Return(&user.DefaultInfo{Name: "test-user"}, nil) - storage := NewREST(requestAuthenticator, successfulIssuer(ctrl), schema.GroupResource{}, auditLogger) + storage := NewREST(requestAuthenticator, successfulIssuer(ctrl), schema.GroupResource{}, auditLogger, frozenClock) + + fakeReqContext := audit.WithAuditContext(context.Background()) + audit.WithAuditID(fakeReqContext, "fake-audit-id") + validationFunctionWasCalled := false var validationFunctionSawTokenValue string + response, err := storage.Create( - context.Background(), + fakeReqContext, req, func(ctx context.Context, obj runtime.Object) error { credentialRequest, _ := obj.(*loginapi.TokenCredentialRequest) @@ -316,10 +355,22 @@ func TestCreate(t *testing.T) { r.NotEmpty(response) r.True(validationFunctionWasCalled) r.Empty(validationFunctionSawTokenValue) + + wantAuditLog = []testutil.WantedAuditLog{ + testutil.WantAuditLog("TokenCredentialRequest", map[string]any{ + "auditID": "fake-audit-id", + "authenticated": true, + "expires": "2024-09-12T04:30:56Z", // this is frozenNow + 5 minutes in UTC + "personalInfo": map[string]any{ + "username": "test-user", + "groups": []any{}, + }, + }), + } }) it("CreateFailsWhenRequestOptionsDryRunIsNotEmpty", func() { - response, err := NewREST(nil, nil, schema.GroupResource{}, auditLogger).Create( + response, err := NewREST(nil, nil, schema.GroupResource{}, auditLogger, frozenClock).Create( genericapirequest.NewContext(), validCredentialRequest(), rest.ValidateAllObjectFunc, @@ -333,7 +384,7 @@ func TestCreate(t *testing.T) { }) it("CreateFailsWhenNamespaceIsNotEmpty", func() { - response, err := NewREST(nil, nil, schema.GroupResource{}, auditLogger).Create( + response, err := NewREST(nil, nil, schema.GroupResource{}, auditLogger, frozenClock).Create( genericapirequest.WithNamespace(genericapirequest.NewContext(), "some-ns"), validCredentialRequest(), rest.ValidateAllObjectFunc, @@ -352,9 +403,12 @@ func requireOneLogStatement(r *require.Assertions, logger *testutil.TranscriptLo r.Contains(transcript[0].Message, messageContains) } -func callCreate(ctx context.Context, storage *REST, obj runtime.Object) (runtime.Object, error) { +func callCreate(storage *REST, obj runtime.Object) (runtime.Object, error) { + fakeReqContext := audit.WithAuditContext(context.Background()) + audit.WithAuditID(fakeReqContext, "fake-audit-id") + return storage.Create( - ctx, + fakeReqContext, obj, rest.ValidateAllObjectFunc, &metav1.CreateOptions{