Add request logging to the create LoginRequest endpoint

Signed-off-by: Andrew Keesler <akeesler@vmware.com>

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
 )
 

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
+	return loginRequest, nil
-	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)
-		}
-	}
 
-	// the incoming context could have an audience attached to it technically
+func traceSuccess(t *trace.Trace, user user.Info, webhookAuthenticated bool, placeholderNameAuthenticated bool) {
-	// sine we do not want to handle audiences right now, do not pass it through directly
+	userID := "<none>"
-	// instead we just propagate cancellation of the parent context
+	if user != nil {
-	cancelCtx, cancel := context.WithCancel(context.Background())
+		userID = user.GetUID()
-	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
 	}
-	if !authenticated || authResponse.User == nil || authResponse.User.GetName() == "" {
+	t.Step("success",
-		return failureResponse(), nil
+		trace.Field{Key: "userID", Value: userID},
-	}
+		trace.Field{Key: "idpAuthenticated", Value: webhookAuthenticated},
-
+		trace.Field{Key: "placeholderNameAuthenticated", Value: placeholderNameAuthenticated},
-	certPEM, keyPEM, err := r.issuer.IssuePEM(
-		pkix.Name{
-			CommonName:   authResponse.User.GetName(),
-			Organization: authResponse.User.GetGroups(),
-		},
-		[]string{},
-		clientCertificateTTL,
 	)
-	if err != nil {
+}
-		klog.Warningf("failed to issue short lived client certificate: %v", err)
-		return failureResponse(), nil
-	}
 
-	return &placeholderapi.LoginRequest{
+func traceValidationFailure(t *trace.Trace, msg string) {
-		Status: placeholderapi.LoginRequestStatus{
+	t.Step("failure",
-			Credential: &placeholderapi.LoginRequestCredential{
+		trace.Field{Key: "failureType", Value: "request validation"},
-				ExpirationTimestamp:   metav1.NewTime(time.Now().UTC().Add(clientCertificateTTL)),
+		trace.Field{Key: "msg", Value: msg},
-				ClientCertificateData: string(certPEM),
+	)
-				ClientKeyData:         string(keyPEM),
+}
-			},
+
-			User: &placeholderapi.User{
+func traceFailureWithError(t *trace.Trace, failureType string, err error) {
-				Name:   authResponse.User.GetName(),
+	t.Step("failure",
-				Groups: authResponse.User.GetGroups(),
+		trace.Field{Key: "failureType", Value: failureType},
-			},
+		trace.Field{Key: "msg", Value: err.Error()},
-		},
+	)
-	}, nil
 }
 
 func failureResponse() *placeholderapi.LoginRequest {

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:<none>,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:<none>,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(),
+				&notALoginRequest,
+				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(),
-		&notALoginRequest,
-		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")
-}

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
+}