From f10c61f5915ac58d51d099e4fd4fd94b4c647d88 Mon Sep 17 00:00:00 2001 From: Ryan Richard Date: Thu, 6 Aug 2020 15:14:30 -0700 Subject: [PATCH] Add request logging to the create LoginRequest endpoint Signed-off-by: Andrew Keesler --- go.mod | 2 + internal/registry/loginrequest/rest.go | 158 +++-- internal/registry/loginrequest/rest_test.go | 716 +++++++++++--------- internal/testutil/transcript_logger.go | 59 ++ 4 files changed, 543 insertions(+), 392 deletions(-) create mode 100644 internal/testutil/transcript_logger.go diff --git a/go.mod b/go.mod index b73e5989..32dae393 100644 --- a/go.mod +++ b/go.mod @@ -3,6 +3,7 @@ module github.com/suzerain-io/placeholder-name go 1.14 require ( + github.com/go-logr/logr v0.2.0 github.com/golang/mock v1.4.3 github.com/golangci/golangci-lint v1.29.0 github.com/google/go-cmp v0.5.0 @@ -20,6 +21,7 @@ require ( k8s.io/component-base v0.19.0-rc.0 k8s.io/klog/v2 v2.2.0 k8s.io/kube-aggregator v0.19.0-rc.0 + k8s.io/utils v0.0.0-20200619165400-6e3d28b6ed19 sigs.k8s.io/yaml v1.2.0 ) diff --git a/internal/registry/loginrequest/rest.go b/internal/registry/loginrequest/rest.go index c4bc4ed9..145d7afc 100644 --- a/internal/registry/loginrequest/rest.go +++ b/internal/registry/loginrequest/rest.go @@ -17,8 +17,9 @@ import ( "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/util/validation/field" "k8s.io/apiserver/pkg/authentication/authenticator" + "k8s.io/apiserver/pkg/authentication/user" "k8s.io/apiserver/pkg/registry/rest" - "k8s.io/klog/v2" + "k8s.io/utils/trace" placeholderapi "github.com/suzerain-io/placeholder-name-api/pkg/apis/placeholder" ) @@ -58,29 +59,104 @@ func (r *REST) NamespaceScoped() bool { } func (r *REST) Create(ctx context.Context, obj runtime.Object, createValidation rest.ValidateObjectFunc, options *metav1.CreateOptions) (runtime.Object, error) { + t := trace.FromContext(ctx).Nest("create LoginRequest") + defer t.Log() + + loginRequest, err := validateRequest(ctx, obj, createValidation, options, t) + if err != nil { + return nil, err + } + + // The incoming context could have an audience. Since we do not want to handle audiences right now, do not pass it + // through directly to the authentication webhook. Instead only propagate cancellation of the parent context. + cancelCtx, cancel := context.WithCancel(context.Background()) + defer cancel() + go func() { + select { + case <-ctx.Done(): + cancel() + case <-cancelCtx.Done(): + } + }() + + authResponse, authenticated, err := r.webhook.AuthenticateToken(cancelCtx, loginRequest.Spec.Token.Value) + if err != nil { + traceFailureWithError(t, "webhook authentication", err) + return failureResponse(), nil + } + if !authenticated || authResponse.User == nil || authResponse.User.GetName() == "" { + traceSuccess(t, authResponse.User, authenticated, false) + return failureResponse(), nil + } + + username := authResponse.User.GetName() + groups := authResponse.User.GetGroups() + + certPEM, keyPEM, err := r.issuer.IssuePEM( + pkix.Name{ + CommonName: username, + Organization: groups, + }, + []string{}, + clientCertificateTTL, + ) + if err != nil { + traceFailureWithError(t, "cert issuer", err) + return failureResponse(), nil + } + + traceSuccess(t, authResponse.User, authenticated, true) + + return &placeholderapi.LoginRequest{ + Status: placeholderapi.LoginRequestStatus{ + Credential: &placeholderapi.LoginRequestCredential{ + ExpirationTimestamp: metav1.NewTime(time.Now().UTC().Add(clientCertificateTTL)), + ClientCertificateData: string(certPEM), + ClientKeyData: string(keyPEM), + }, + User: &placeholderapi.User{ + Name: username, + Groups: groups, + }, + }, + }, nil +} + +func validateRequest(ctx context.Context, obj runtime.Object, createValidation rest.ValidateObjectFunc, options *metav1.CreateOptions, t *trace.Trace) (*placeholderapi.LoginRequest, error) { loginRequest, ok := obj.(*placeholderapi.LoginRequest) if !ok { + traceValidationFailure(t, "not a LoginRequest") return nil, apierrors.NewBadRequest(fmt.Sprintf("not a LoginRequest: %#v", obj)) } - // TODO refactor all validation checks into a validation function in another package (e.g. see subjectaccessreqview api in k8s) - if len(loginRequest.Spec.Type) == 0 { + traceValidationFailure(t, "type must be supplied") errs := field.ErrorList{field.Required(field.NewPath("spec", "type"), "type must be supplied")} return nil, apierrors.NewInvalid(placeholderapi.Kind(loginRequest.Kind), loginRequest.Name, errs) } if loginRequest.Spec.Type != placeholderapi.TokenLoginCredentialType { + traceValidationFailure(t, "unrecognized type") errs := field.ErrorList{field.Invalid(field.NewPath("spec", "type"), loginRequest.Spec.Type, "unrecognized type")} return nil, apierrors.NewInvalid(placeholderapi.Kind(loginRequest.Kind), loginRequest.Name, errs) } token := loginRequest.Spec.Token if token == nil || len(token.Value) == 0 { + traceValidationFailure(t, "token must be supplied") errs := field.ErrorList{field.Required(field.NewPath("spec", "token", "value"), "token must be supplied")} return nil, apierrors.NewInvalid(placeholderapi.Kind(loginRequest.Kind), loginRequest.Name, errs) } + // just a sanity check, not sure how to honor a dry run on a virtual API + if options != nil { + if len(options.DryRun) != 0 { + traceValidationFailure(t, "dryRun not supported") + errs := field.ErrorList{field.NotSupported(field.NewPath("dryRun"), options.DryRun, nil)} + return nil, apierrors.NewInvalid(placeholderapi.Kind(loginRequest.Kind), loginRequest.Name, errs) + } + } + // let dynamic admission webhooks have a chance to validate (but not mutate) as well // TODO Since we are an aggregated API, we should investigate to see if the kube API server is already invoking admission hooks for us. // Even if it is, its okay to call it again here. However, if the kube API server is already calling the webhooks and passing @@ -91,66 +167,38 @@ func (r *REST) Create(ctx context.Context, obj runtime.Object, createValidation loginRequestCopy, _ := requestForValidation.(*placeholderapi.LoginRequest) loginRequestCopy.Spec.Token.Value = "" if err := createValidation(ctx, requestForValidation); err != nil { + traceFailureWithError(t, "validation webhook", err) return nil, err } } - // just a sanity check, not sure how to honor a dry run on a virtual API - if options != nil { - if len(options.DryRun) != 0 { - errs := field.ErrorList{field.NotSupported(field.NewPath("dryRun"), options.DryRun, nil)} - return nil, apierrors.NewInvalid(placeholderapi.Kind(loginRequest.Kind), loginRequest.Name, errs) - } - } + return loginRequest, nil +} - // the incoming context could have an audience attached to it technically - // sine we do not want to handle audiences right now, do not pass it through directly - // instead we just propagate cancellation of the parent context - cancelCtx, cancel := context.WithCancel(context.Background()) - defer cancel() - go func() { - select { - case <-ctx.Done(): - cancel() - case <-cancelCtx.Done(): - } - }() - - authResponse, authenticated, err := r.webhook.AuthenticateToken(cancelCtx, token.Value) - if err != nil { - klog.Warningf("webhook authentication failure: %v", err) - return failureResponse(), nil +func traceSuccess(t *trace.Trace, user user.Info, webhookAuthenticated bool, placeholderNameAuthenticated bool) { + userID := "" + if user != nil { + userID = user.GetUID() } - if !authenticated || authResponse.User == nil || authResponse.User.GetName() == "" { - return failureResponse(), nil - } - - certPEM, keyPEM, err := r.issuer.IssuePEM( - pkix.Name{ - CommonName: authResponse.User.GetName(), - Organization: authResponse.User.GetGroups(), - }, - []string{}, - clientCertificateTTL, + t.Step("success", + trace.Field{Key: "userID", Value: userID}, + trace.Field{Key: "idpAuthenticated", Value: webhookAuthenticated}, + trace.Field{Key: "placeholderNameAuthenticated", Value: placeholderNameAuthenticated}, ) - if err != nil { - klog.Warningf("failed to issue short lived client certificate: %v", err) - return failureResponse(), nil - } +} - return &placeholderapi.LoginRequest{ - Status: placeholderapi.LoginRequestStatus{ - Credential: &placeholderapi.LoginRequestCredential{ - ExpirationTimestamp: metav1.NewTime(time.Now().UTC().Add(clientCertificateTTL)), - ClientCertificateData: string(certPEM), - ClientKeyData: string(keyPEM), - }, - User: &placeholderapi.User{ - Name: authResponse.User.GetName(), - Groups: authResponse.User.GetGroups(), - }, - }, - }, nil +func traceValidationFailure(t *trace.Trace, msg string) { + t.Step("failure", + trace.Field{Key: "failureType", Value: "request validation"}, + trace.Field{Key: "msg", Value: msg}, + ) +} + +func traceFailureWithError(t *trace.Trace, failureType string, err error) { + t.Step("failure", + trace.Field{Key: "failureType", Value: failureType}, + trace.Field{Key: "msg", Value: err.Error()}, + ) } func failureResponse() *placeholderapi.LoginRequest { diff --git a/internal/registry/loginrequest/rest_test.go b/internal/registry/loginrequest/rest_test.go index 0d89152b..66d341fe 100644 --- a/internal/registry/loginrequest/rest_test.go +++ b/internal/registry/loginrequest/rest_test.go @@ -14,6 +14,7 @@ import ( "time" "github.com/golang/mock/gomock" + "github.com/sclevine/spec" "github.com/stretchr/testify/require" apierrors "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -22,9 +23,11 @@ import ( "k8s.io/apiserver/pkg/authentication/user" genericapirequest "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/apiserver/pkg/registry/rest" + "k8s.io/klog/v2" placeholderapi "github.com/suzerain-io/placeholder-name-api/pkg/apis/placeholder" "github.com/suzerain-io/placeholder-name/internal/mocks/mockcertissuer" + "github.com/suzerain-io/placeholder-name/internal/testutil" ) type contextKey struct{} @@ -57,6 +60,381 @@ func (f *FakeToken) AuthenticateToken(ctx context.Context, token string) (*authe return f.returnResponse, !f.returnUnauthenticated, f.returnErr } +func TestCreate(t *testing.T) { + spec.Run(t, "create", func(t *testing.T, when spec.G, it spec.S) { + var r *require.Assertions + var ctrl *gomock.Controller + var logger *testutil.TranscriptLogger + + it.Before(func() { + r = require.New(t) + ctrl = gomock.NewController(t) + logger = testutil.NewTranscriptLogger(t) + klog.SetLogger(logger) // this is unfortunately a global logger, so can't run these tests in parallel :( + }) + + it.After(func() { + klog.SetLogger(nil) + ctrl.Finish() + }) + + it("CreateSucceedsWhenGivenATokenAndTheWebhookAuthenticatesTheToken", func() { + webhook := FakeToken{ + returnResponse: &authenticator.Response{ + User: &user.DefaultInfo{ + Name: "test-user", + UID: "test-user-uid", + Groups: []string{"test-group-1", "test-group-2"}, + }, + }, + returnUnauthenticated: false, + } + + issuer := mockcertissuer.NewMockCertIssuer(ctrl) + issuer.EXPECT().IssuePEM( + pkix.Name{ + CommonName: "test-user", + Organization: []string{"test-group-1", "test-group-2"}}, + []string{}, + 1*time.Hour, + ).Return([]byte("test-cert"), []byte("test-key"), nil) + + storage := NewREST(&webhook, issuer) + requestToken := "a token" + + response, err := callCreate(context.Background(), storage, validLoginRequestWithToken(requestToken)) + + r.NoError(err) + r.IsType(&placeholderapi.LoginRequest{}, response) + + expires := response.(*placeholderapi.LoginRequest).Status.Credential.ExpirationTimestamp + r.NotNil(expires) + r.InDelta(time.Now().Add(1*time.Hour).Unix(), expires.Unix(), 5) + response.(*placeholderapi.LoginRequest).Status.Credential.ExpirationTimestamp = metav1.Time{} + + r.Equal(response, &placeholderapi.LoginRequest{ + Status: placeholderapi.LoginRequestStatus{ + User: &placeholderapi.User{ + Name: "test-user", + Groups: []string{"test-group-1", "test-group-2"}, + }, + Credential: &placeholderapi.LoginRequestCredential{ + ExpirationTimestamp: metav1.Time{}, + ClientCertificateData: "test-cert", + ClientKeyData: "test-key", + }, + Message: "", + }, + }) + r.Equal(requestToken, webhook.calledWithToken) + requireOneLogStatement(r, logger, `"success" userID:test-user-uid,idpAuthenticated:true`) + }) + + it("CreateFailsWithValidTokenWhenCertIssuerFails", func() { + webhook := FakeToken{ + returnResponse: &authenticator.Response{ + User: &user.DefaultInfo{ + Name: "test-user", + Groups: []string{"test-group-1", "test-group-2"}, + }, + }, + returnUnauthenticated: false, + } + + issuer := mockcertissuer.NewMockCertIssuer(ctrl) + issuer.EXPECT(). + IssuePEM(gomock.Any(), gomock.Any(), gomock.Any()). + Return(nil, nil, fmt.Errorf("some certificate authority error")) + + storage := NewREST(&webhook, issuer) + requestToken := "a token" + + response, err := callCreate(context.Background(), storage, validLoginRequestWithToken(requestToken)) + requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) + r.Equal(requestToken, webhook.calledWithToken) + requireOneLogStatement(r, logger, `"failure" failureType:cert issuer,msg:some certificate authority error`) + }) + + it("CreateSucceedsWithAnUnauthenticatedStatusWhenGivenATokenAndTheWebhookReturnsUnauthenticatedWithUserId", func() { + webhook := FakeToken{ + returnResponse: &authenticator.Response{ + User: &user.DefaultInfo{UID: "test-user-uid"}, + }, + returnUnauthenticated: true, + } + storage := NewREST(&webhook, nil) + requestToken := "a token" + + response, err := callCreate(context.Background(), storage, validLoginRequestWithToken(requestToken)) + + requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) + r.Equal(requestToken, webhook.calledWithToken) + requireOneLogStatement(r, logger, `"success" userID:test-user-uid,idpAuthenticated:false,placeholderNameAuthenticated:false`) + }) + + it("CreateSucceedsWithAnUnauthenticatedStatusWhenGivenATokenAndTheWebhookReturnsUnauthenticatedWithNilUser", func() { + webhook := FakeToken{ + returnResponse: &authenticator.Response{User: nil}, + returnUnauthenticated: true, + } + storage := NewREST(&webhook, nil) + requestToken := "a token" + + response, err := callCreate(context.Background(), storage, validLoginRequestWithToken(requestToken)) + + requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) + r.Equal(requestToken, webhook.calledWithToken) + requireOneLogStatement(r, logger, `"success" userID:,idpAuthenticated:false,placeholderNameAuthenticated:false`) + }) + + it("CreateSucceedsWithAnUnauthenticatedStatusWhenWebhookFails", func() { + webhook := FakeToken{ + returnErr: errors.New("some webhook error"), + } + storage := NewREST(&webhook, nil) + + response, err := callCreate(context.Background(), storage, validLoginRequest()) + + requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) + requireOneLogStatement(r, logger, `"failure" failureType:webhook authentication,msg:some webhook error`) + }) + + it("CreateSucceedsWithAnUnauthenticatedStatusWhenWebhookDoesNotReturnAnyUserInfo", func() { + webhook := FakeToken{ + returnResponse: &authenticator.Response{}, + returnUnauthenticated: false, + } + storage := NewREST(&webhook, nil) + + response, err := callCreate(context.Background(), storage, validLoginRequest()) + + requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) + requireOneLogStatement(r, logger, `"success" userID:,idpAuthenticated:true,placeholderNameAuthenticated:false`) + }) + + it("CreateSucceedsWithAnUnauthenticatedStatusWhenWebhookReturnsAnEmptyUsername", func() { + webhook := FakeToken{ + returnResponse: &authenticator.Response{ + User: &user.DefaultInfo{ + Name: "", + }, + }, + } + storage := NewREST(&webhook, nil) + + response, err := callCreate(context.Background(), storage, validLoginRequest()) + + requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) + requireOneLogStatement(r, logger, `"success" userID:,idpAuthenticated:true,placeholderNameAuthenticated:false`) + }) + + it("CreateDoesNotPassAdditionalContextInfoToTheWebhook", func() { + webhook := FakeToken{ + returnResponse: webhookSuccessResponse(), + } + storage := NewREST(&webhook, successfulIssuer(ctrl)) + ctx := context.WithValue(context.Background(), contextKey{}, "context-value") + + _, err := callCreate(ctx, storage, validLoginRequest()) + + r.NoError(err) + r.Nil(webhook.calledWithContext.Value("context-key")) + }) + + it("CreateFailsWhenGivenTheWrongInputType", func() { + notALoginRequest := runtime.Unknown{} + response, err := NewREST(&FakeToken{}, nil).Create( + genericapirequest.NewContext(), + ¬ALoginRequest, + rest.ValidateAllObjectFunc, + &metav1.CreateOptions{}) + + requireAPIError(t, response, err, apierrors.IsBadRequest, "not a LoginRequest") + requireOneLogStatement(r, logger, `"failure" failureType:request validation,msg:not a LoginRequest`) + }) + + it("CreateFailsWhenTokenIsNilInRequest", func() { + storage := NewREST(&FakeToken{}, nil) + response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ + Type: placeholderapi.TokenLoginCredentialType, + Token: nil, + })) + + requireAPIError(t, response, err, apierrors.IsInvalid, + `.placeholder.suzerain-io.github.io "request name" is invalid: spec.token.value: Required value: token must be supplied`) + requireOneLogStatement(r, logger, `"failure" failureType:request validation,msg:token must be supplied`) + }) + + it("CreateFailsWhenTypeInRequestIsMissing", func() { + storage := NewREST(&FakeToken{}, nil) + response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ + Type: "", + Token: &placeholderapi.LoginRequestTokenCredential{Value: "a token"}, + })) + + requireAPIError(t, response, err, apierrors.IsInvalid, + `.placeholder.suzerain-io.github.io "request name" is invalid: spec.type: Required value: type must be supplied`) + requireOneLogStatement(r, logger, `"failure" failureType:request validation,msg:type must be supplied`) + }) + + it("CreateFailsWhenTypeInRequestIsNotLegal", func() { + storage := NewREST(&FakeToken{}, nil) + response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ + Type: "this in an invalid type", + Token: &placeholderapi.LoginRequestTokenCredential{Value: "a token"}, + })) + + requireAPIError(t, response, err, apierrors.IsInvalid, + `.placeholder.suzerain-io.github.io "request name" is invalid: spec.type: Invalid value: "this in an invalid type": unrecognized type`) + requireOneLogStatement(r, logger, `"failure" failureType:request validation,msg:unrecognized type`) + }) + + it("CreateFailsWhenTokenValueIsEmptyInRequest", func() { + storage := NewREST(&FakeToken{}, nil) + response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ + Type: placeholderapi.TokenLoginCredentialType, + Token: &placeholderapi.LoginRequestTokenCredential{Value: ""}, + })) + + requireAPIError(t, response, err, apierrors.IsInvalid, + `.placeholder.suzerain-io.github.io "request name" is invalid: spec.token.value: Required value: token must be supplied`) + requireOneLogStatement(r, logger, `"failure" failureType:request validation,msg:token must be supplied`) + }) + + it("CreateFailsWhenValidationFails", func() { + storage := NewREST(&FakeToken{}, nil) + response, err := storage.Create( + context.Background(), + validLoginRequest(), + func(ctx context.Context, obj runtime.Object) error { + return fmt.Errorf("some validation error") + }, + &metav1.CreateOptions{}) + r.Nil(response) + r.EqualError(err, "some validation error") + requireOneLogStatement(r, logger, `"failure" failureType:validation webhook,msg:some validation error`) + }) + + it("CreateDoesNotAllowValidationFunctionToMutateRequest", func() { + webhook := FakeToken{ + returnResponse: webhookSuccessResponse(), + } + storage := NewREST(&webhook, successfulIssuer(ctrl)) + requestToken := "a token" + response, err := storage.Create( + context.Background(), + validLoginRequestWithToken(requestToken), + func(ctx context.Context, obj runtime.Object) error { + loginRequest, _ := obj.(*placeholderapi.LoginRequest) + loginRequest.Spec.Token.Value = "foobaz" + return nil + }, + &metav1.CreateOptions{}) + r.NoError(err) + r.NotEmpty(response) + r.Equal(requestToken, webhook.calledWithToken) // i.e. not called with foobaz + }) + + it("CreateDoesNotAllowValidationFunctionToSeeTheActualRequestToken", func() { + webhook := FakeToken{ + returnResponse: webhookSuccessResponse(), + } + + storage := NewREST(&webhook, successfulIssuer(ctrl)) + validationFunctionWasCalled := false + var validationFunctionSawTokenValue string + response, err := storage.Create( + context.Background(), + validLoginRequest(), + func(ctx context.Context, obj runtime.Object) error { + loginRequest, _ := obj.(*placeholderapi.LoginRequest) + validationFunctionWasCalled = true + validationFunctionSawTokenValue = loginRequest.Spec.Token.Value + return nil + }, + &metav1.CreateOptions{}) + r.NoError(err) + r.NotEmpty(response) + r.True(validationFunctionWasCalled) + r.Empty(validationFunctionSawTokenValue) + }) + + it("CreateFailsWhenRequestOptionsDryRunIsNotEmpty", func() { + response, err := NewREST(&FakeToken{}, nil).Create( + genericapirequest.NewContext(), + validLoginRequest(), + rest.ValidateAllObjectFunc, + &metav1.CreateOptions{ + DryRun: []string{"some dry run flag"}, + }) + + requireAPIError(t, response, err, apierrors.IsInvalid, + `.placeholder.suzerain-io.github.io "request name" is invalid: dryRun: Unsupported value: []string{"some dry run flag"}`) + requireOneLogStatement(r, logger, `"failure" failureType:request validation,msg:dryRun not supported`) + }) + + it("CreateCancelsTheWebhookInvocationWhenTheCallToCreateIsCancelledItself", func() { + webhookStartedRunningNotificationChan := make(chan bool) + webhook := FakeToken{ + timeout: time.Second * 2, + webhookStartedRunningNotificationChan: webhookStartedRunningNotificationChan, + returnResponse: webhookSuccessResponse(), + } + storage := NewREST(&webhook, successfulIssuer(ctrl)) + ctx, cancel := context.WithCancel(context.Background()) + + c := make(chan bool) + go func() { + _, err := callCreate(ctx, storage, validLoginRequest()) + c <- true + r.NoError(err) + }() + + r.False(webhook.cancelled) + r.False(webhook.reachedTimeout) + <-webhookStartedRunningNotificationChan // wait long enough to make sure that the webhook has started + cancel() // cancel the context that was passed to storage.Create() above + <-c // wait for the above call to storage.Create() to be finished + r.True(webhook.cancelled) + r.False(webhook.reachedTimeout) + r.Equal(context.Canceled, webhook.calledWithContext.Err()) // the inner context is cancelled + }) + + it("CreateAllowsTheWebhookInvocationToFinishWhenTheCallToCreateIsNotCancelledItself", func() { + webhookStartedRunningNotificationChan := make(chan bool) + webhook := FakeToken{ + timeout: 0, + webhookStartedRunningNotificationChan: webhookStartedRunningNotificationChan, + returnResponse: webhookSuccessResponse(), + } + storage := NewREST(&webhook, successfulIssuer(ctrl)) + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + c := make(chan bool) + go func() { + _, err := callCreate(ctx, storage, validLoginRequest()) + c <- true + r.NoError(err) + }() + + r.False(webhook.cancelled) + r.False(webhook.reachedTimeout) + <-webhookStartedRunningNotificationChan // wait long enough to make sure that the webhook has started + <-c // wait for the above call to storage.Create() to be finished + r.False(webhook.cancelled) + r.True(webhook.reachedTimeout) + r.Equal(context.Canceled, webhook.calledWithContext.Err()) // the inner context is cancelled (in this case by the "defer") + }) + }, spec.Sequential()) +} + +func requireOneLogStatement(r *require.Assertions, logger *testutil.TranscriptLogger, messageContains string) { + r.Len(logger.Transcript, 1) + r.Equal("info", logger.Transcript[0].Level) + r.Contains(logger.Transcript[0].Message, messageContains) +} + func callCreate(ctx context.Context, storage *REST, loginRequest *placeholderapi.LoginRequest) (runtime.Object, error) { return storage.Create( ctx, @@ -107,6 +485,7 @@ func requireAPIError(t *testing.T, response runtime.Object, err error, expectedE } func requireSuccessfulResponseWithAuthenticationFailureMessage(t *testing.T, err error, response runtime.Object) { + t.Helper() require.NoError(t, err) require.Equal(t, response, &placeholderapi.LoginRequest{ Status: placeholderapi.LoginRequestStatus{ @@ -123,340 +502,3 @@ func successfulIssuer(ctrl *gomock.Controller) CertIssuer { Return([]byte("test-cert"), []byte("test-key"), nil) return issuer } - -func TestCreateSucceedsWhenGivenATokenAndTheWebhookAuthenticatesTheToken(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - webhook := FakeToken{ - returnResponse: &authenticator.Response{ - User: &user.DefaultInfo{ - Name: "test-user", - Groups: []string{"test-group-1", "test-group-2"}, - }, - }, - returnUnauthenticated: false, - } - - issuer := mockcertissuer.NewMockCertIssuer(ctrl) - issuer.EXPECT().IssuePEM( - pkix.Name{ - CommonName: "test-user", - Organization: []string{"test-group-1", "test-group-2"}}, - []string{}, - 1*time.Hour, - ).Return([]byte("test-cert"), []byte("test-key"), nil) - - storage := NewREST(&webhook, issuer) - requestToken := "a token" - - response, err := callCreate(context.Background(), storage, validLoginRequestWithToken(requestToken)) - - require.NoError(t, err) - require.IsType(t, &placeholderapi.LoginRequest{}, response) - - expires := response.(*placeholderapi.LoginRequest).Status.Credential.ExpirationTimestamp - require.NotNil(t, expires) - require.InDelta(t, time.Now().Add(1*time.Hour).Unix(), expires.Unix(), 5) - response.(*placeholderapi.LoginRequest).Status.Credential.ExpirationTimestamp = metav1.Time{} - - require.Equal(t, response, &placeholderapi.LoginRequest{ - Status: placeholderapi.LoginRequestStatus{ - User: &placeholderapi.User{ - Name: "test-user", - Groups: []string{"test-group-1", "test-group-2"}, - }, - Credential: &placeholderapi.LoginRequestCredential{ - ExpirationTimestamp: metav1.Time{}, - ClientCertificateData: "test-cert", - ClientKeyData: "test-key", - }, - Message: "", - }, - }) - require.Equal(t, requestToken, webhook.calledWithToken) -} - -func TestCreateFailsWithValidTokenWhenCertIssuerFails(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - webhook := FakeToken{ - returnResponse: &authenticator.Response{ - User: &user.DefaultInfo{ - Name: "test-user", - Groups: []string{"test-group-1", "test-group-2"}, - }, - }, - returnUnauthenticated: false, - } - - issuer := mockcertissuer.NewMockCertIssuer(ctrl) - issuer.EXPECT(). - IssuePEM(gomock.Any(), gomock.Any(), gomock.Any()). - Return(nil, nil, fmt.Errorf("some certificate authority error")) - - storage := NewREST(&webhook, issuer) - requestToken := "a token" - - response, err := callCreate(context.Background(), storage, validLoginRequestWithToken(requestToken)) - requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) - require.Equal(t, requestToken, webhook.calledWithToken) -} - -func TestCreateSucceedsWithAnUnauthenticatedStatusWhenGivenATokenAndTheWebhookDoesNotAuthenticateTheToken(t *testing.T) { - webhook := FakeToken{ - returnUnauthenticated: true, - } - storage := NewREST(&webhook, nil) - requestToken := "a token" - - response, err := callCreate(context.Background(), storage, validLoginRequestWithToken(requestToken)) - - requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) - require.Equal(t, requestToken, webhook.calledWithToken) -} - -func TestCreateSucceedsWithAnUnauthenticatedStatusWhenWebhookFails(t *testing.T) { - webhook := FakeToken{ - returnErr: errors.New("some webhook error"), - } - storage := NewREST(&webhook, nil) - - response, err := callCreate(context.Background(), storage, validLoginRequest()) - - requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) -} - -func TestCreateSucceedsWithAnUnauthenticatedStatusWhenWebhookDoesNotReturnAnyUserInfo(t *testing.T) { - webhook := FakeToken{ - returnResponse: &authenticator.Response{}, - } - storage := NewREST(&webhook, nil) - - response, err := callCreate(context.Background(), storage, validLoginRequest()) - - requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) -} - -func TestCreateSucceedsWithAnUnauthenticatedStatusWhenWebhookReturnsAnEmptyUsername(t *testing.T) { - webhook := FakeToken{ - returnResponse: &authenticator.Response{ - User: &user.DefaultInfo{ - Name: "", - }, - }, - } - storage := NewREST(&webhook, nil) - - response, err := callCreate(context.Background(), storage, validLoginRequest()) - - requireSuccessfulResponseWithAuthenticationFailureMessage(t, err, response) -} - -func TestCreateDoesNotPassAdditionalContextInfoToTheWebhook(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - webhook := FakeToken{ - returnResponse: webhookSuccessResponse(), - } - storage := NewREST(&webhook, successfulIssuer(ctrl)) - ctx := context.WithValue(context.Background(), contextKey{}, "context-value") - - _, err := callCreate(ctx, storage, validLoginRequest()) - - require.NoError(t, err) - require.Nil(t, webhook.calledWithContext.Value("context-key")) -} - -func TestCreateFailsWhenGivenTheWrongInputType(t *testing.T) { - notALoginRequest := runtime.Unknown{} - response, err := NewREST(&FakeToken{}, nil).Create( - genericapirequest.NewContext(), - ¬ALoginRequest, - rest.ValidateAllObjectFunc, - &metav1.CreateOptions{}) - - requireAPIError(t, response, err, apierrors.IsBadRequest, "not a LoginRequest") -} - -func TestCreateFailsWhenTokenIsNilInRequest(t *testing.T) { - storage := NewREST(&FakeToken{}, nil) - response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ - Type: placeholderapi.TokenLoginCredentialType, - Token: nil, - })) - - requireAPIError(t, response, err, apierrors.IsInvalid, - `.placeholder.suzerain-io.github.io "request name" is invalid: spec.token.value: Required value: token must be supplied`) -} - -func TestCreateFailsWhenTypeInRequestIsMissing(t *testing.T) { - storage := NewREST(&FakeToken{}, nil) - response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ - Type: "", - Token: &placeholderapi.LoginRequestTokenCredential{Value: "a token"}, - })) - - requireAPIError(t, response, err, apierrors.IsInvalid, - `.placeholder.suzerain-io.github.io "request name" is invalid: spec.type: Required value: type must be supplied`) -} - -func TestCreateFailsWhenTypeInRequestIsNotLegal(t *testing.T) { - storage := NewREST(&FakeToken{}, nil) - response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ - Type: "this in an invalid type", - Token: &placeholderapi.LoginRequestTokenCredential{Value: "a token"}, - })) - - requireAPIError(t, response, err, apierrors.IsInvalid, - `.placeholder.suzerain-io.github.io "request name" is invalid: spec.type: Invalid value: "this in an invalid type": unrecognized type`) -} - -func TestCreateFailsWhenTokenValueIsEmptyInRequest(t *testing.T) { - storage := NewREST(&FakeToken{}, nil) - response, err := callCreate(context.Background(), storage, loginRequest(placeholderapi.LoginRequestSpec{ - Type: placeholderapi.TokenLoginCredentialType, - Token: &placeholderapi.LoginRequestTokenCredential{Value: ""}, - })) - - requireAPIError(t, response, err, apierrors.IsInvalid, - `.placeholder.suzerain-io.github.io "request name" is invalid: spec.token.value: Required value: token must be supplied`) -} - -func TestCreateFailsWhenValidationFails(t *testing.T) { - storage := NewREST(&FakeToken{}, nil) - response, err := storage.Create( - context.Background(), - validLoginRequest(), - func(ctx context.Context, obj runtime.Object) error { - return fmt.Errorf("some validation error") - }, - &metav1.CreateOptions{}) - require.Nil(t, response) - require.EqualError(t, err, "some validation error") -} - -func TestCreateDoesNotAllowValidationFunctionToMutateRequest(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - webhook := FakeToken{ - returnResponse: webhookSuccessResponse(), - } - storage := NewREST(&webhook, successfulIssuer(ctrl)) - requestToken := "a token" - response, err := storage.Create( - context.Background(), - validLoginRequestWithToken(requestToken), - func(ctx context.Context, obj runtime.Object) error { - loginRequest, _ := obj.(*placeholderapi.LoginRequest) - loginRequest.Spec.Token.Value = "foobaz" - return nil - }, - &metav1.CreateOptions{}) - require.NoError(t, err) - require.NotEmpty(t, response) - require.Equal(t, requestToken, webhook.calledWithToken) // i.e. not called with foobaz -} - -func TestCreateDoesNotAllowValidationFunctionToSeeTheActualRequestToken(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - webhook := FakeToken{ - returnResponse: webhookSuccessResponse(), - } - - storage := NewREST(&webhook, successfulIssuer(ctrl)) - validationFunctionWasCalled := false - var validationFunctionSawTokenValue string - response, err := storage.Create( - context.Background(), - validLoginRequest(), - func(ctx context.Context, obj runtime.Object) error { - loginRequest, _ := obj.(*placeholderapi.LoginRequest) - validationFunctionWasCalled = true - validationFunctionSawTokenValue = loginRequest.Spec.Token.Value - return nil - }, - &metav1.CreateOptions{}) - require.NoError(t, err) - require.NotEmpty(t, response) - require.True(t, validationFunctionWasCalled) - require.Empty(t, validationFunctionSawTokenValue) -} - -func TestCreateFailsWhenRequestOptionsDryRunIsNotEmpty(t *testing.T) { - response, err := NewREST(&FakeToken{}, nil).Create( - genericapirequest.NewContext(), - validLoginRequest(), - rest.ValidateAllObjectFunc, - &metav1.CreateOptions{ - DryRun: []string{"some dry run flag"}, - }) - - requireAPIError(t, response, err, apierrors.IsInvalid, - `.placeholder.suzerain-io.github.io "request name" is invalid: dryRun: Unsupported value: []string{"some dry run flag"}`) -} - -func TestCreateCancelsTheWebhookInvocationWhenTheCallToCreateIsCancelledItself(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - webhookStartedRunningNotificationChan := make(chan bool) - webhook := FakeToken{ - timeout: time.Second * 2, - webhookStartedRunningNotificationChan: webhookStartedRunningNotificationChan, - returnResponse: webhookSuccessResponse(), - } - storage := NewREST(&webhook, successfulIssuer(ctrl)) - ctx, cancel := context.WithCancel(context.Background()) - - c := make(chan bool) - go func() { - _, err := callCreate(ctx, storage, validLoginRequest()) - c <- true - require.NoError(t, err) - }() - - require.False(t, webhook.cancelled) - require.False(t, webhook.reachedTimeout) - <-webhookStartedRunningNotificationChan // wait long enough to make sure that the webhook has started - cancel() // cancel the context that was passed to storage.Create() above - <-c // wait for the above call to storage.Create() to be finished - require.True(t, webhook.cancelled) - require.False(t, webhook.reachedTimeout) - require.Equal(t, context.Canceled, webhook.calledWithContext.Err()) // the inner context is cancelled -} - -func TestCreateAllowsTheWebhookInvocationToFinishWhenTheCallToCreateIsNotCancelledItself(t *testing.T) { - ctrl := gomock.NewController(t) - defer ctrl.Finish() - - webhookStartedRunningNotificationChan := make(chan bool) - webhook := FakeToken{ - timeout: 0, - webhookStartedRunningNotificationChan: webhookStartedRunningNotificationChan, - returnResponse: webhookSuccessResponse(), - } - storage := NewREST(&webhook, successfulIssuer(ctrl)) - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - - c := make(chan bool) - go func() { - _, err := callCreate(ctx, storage, validLoginRequest()) - c <- true - require.NoError(t, err) - }() - - require.False(t, webhook.cancelled) - require.False(t, webhook.reachedTimeout) - <-webhookStartedRunningNotificationChan // wait long enough to make sure that the webhook has started - <-c // wait for the above call to storage.Create() to be finished - require.False(t, webhook.cancelled) - require.True(t, webhook.reachedTimeout) - require.Equal(t, context.Canceled, webhook.calledWithContext.Err()) // the inner context is cancelled (in this case by the "defer") -} diff --git a/internal/testutil/transcript_logger.go b/internal/testutil/transcript_logger.go new file mode 100644 index 00000000..2bf99e7b --- /dev/null +++ b/internal/testutil/transcript_logger.go @@ -0,0 +1,59 @@ +/* +Copyright 2020 VMware, Inc. +SPDX-License-Identifier: Apache-2.0 +*/ + +package testutil + +import ( + "fmt" + "testing" + + "github.com/go-logr/logr" +) + +type TranscriptLogger struct { + t *testing.T + Transcript []TranscriptLogMessage +} + +var _ logr.Logger = &TranscriptLogger{} + +type TranscriptLogMessage struct { + Level string + Message string +} + +func NewTranscriptLogger(t *testing.T) *TranscriptLogger { + return &TranscriptLogger{t: t} +} + +func (log *TranscriptLogger) Info(msg string, keysAndValues ...interface{}) { + log.Transcript = append(log.Transcript, TranscriptLogMessage{ + Level: "info", + Message: fmt.Sprintf(msg, keysAndValues...), + }) +} + +func (log *TranscriptLogger) Error(err error, msg string, keysAndValues ...interface{}) { + log.Transcript = append(log.Transcript, TranscriptLogMessage{ + Level: "error", + Message: fmt.Sprintf("%s: %v -- %v", msg, err, keysAndValues), + }) +} + +func (*TranscriptLogger) Enabled() bool { + return true +} + +func (log *TranscriptLogger) V(_ int) logr.Logger { + return log +} + +func (log *TranscriptLogger) WithName(_ string) logr.Logger { + return log +} + +func (log *TranscriptLogger) WithValues(_ ...interface{}) logr.Logger { + return log +}