diff --git a/internal/registry/clientsecretrequest/rest.go b/internal/registry/clientsecretrequest/rest.go index 7494288f..23ce0ead 100644 --- a/internal/registry/clientsecretrequest/rest.go +++ b/internal/registry/clientsecretrequest/rest.go @@ -128,12 +128,11 @@ func (r *REST) Create(ctx context.Context, obj runtime.Object, createValidation // Find the specified OIDCClient. oidcClient, err := r.oidcClientsClient.Get(ctx, req.Name, metav1.GetOptions{}) if err != nil { + traceFailureWithError(t, "oidcClientsClient.Get", err) if apierrors.IsNotFound(err) { - traceValidationFailure(t, fmt.Sprintf("client %q does not exist", req.Name)) errs := field.ErrorList{field.NotFound(field.NewPath("metadata", "name"), req.Name)} return nil, apierrors.NewInvalid(kindFromContext(ctx), req.Name, errs) } - traceFailureWithError(t, "oidcClientsClient.Get", err) return nil, apierrors.NewInternalError(fmt.Errorf("getting client %q failed", req.Name)) } t.Step("oidcClientsClient.Get") @@ -177,14 +176,15 @@ func (r *REST) Create(ctx context.Context, obj runtime.Object, createValidation if req.Spec.GenerateNewSecret || needsRevoke { // Each bcrypt comparison is expensive, and we do not want a large list to cause wasted CPU. if len(hashes) > 5 { - return nil, apierrors.NewBadRequest( - fmt.Sprintf("OIDCClient %s has too many secrets, spec.revokeOldSecrets must be true", oidcClient.Name), - ) + msg := fmt.Sprintf("OIDCClient %s has too many secrets, spec.revokeOldSecrets must be true", oidcClient.Name) + traceFailure(t, "secretStorage.Set", msg) + return nil, apierrors.NewBadRequest(msg) } // Create or update the storage Secret for client secrets. if err := r.secretStorage.Set(ctx, rv, oidcClient.Name, oidcClient.UID, hashes); err != nil { if apierrors.IsAlreadyExists(err) || apierrors.IsConflict(err) { + traceFailureWithError(t, "secretStorage.Set", err) return nil, apierrors.NewConflict(qualifiedResourceFromContext(ctx), req.Name, fmt.Errorf("multiple concurrent secret generation requests for same client")) } @@ -209,26 +209,29 @@ func (r *REST) validateRequest( obj runtime.Object, createValidation rest.ValidateObjectFunc, options *metav1.CreateOptions, - t *trace.Trace, + tracer *trace.Trace, ) (*clientsecretapi.OIDCClientSecretRequest, error) { clientSecretRequest, ok := obj.(*clientsecretapi.OIDCClientSecretRequest) if !ok { - traceValidationFailure(t, "not an OIDCClientSecretRequest") + traceValidationFailure(tracer, "not an OIDCClientSecretRequest") return nil, apierrors.NewBadRequest(fmt.Sprintf("not an OIDCClientSecretRequest: %#v", obj)) } // Ensure namespace on the object is correct, or error if a conflicting namespace was set in the object. requestNamespace, ok := genericapirequest.NamespaceFrom(ctx) if !ok { - return nil, apierrors.NewInternalError(fmt.Errorf("no namespace information found in request context")) + msg := "no namespace information found in request context" + traceValidationFailure(tracer, msg) + return nil, apierrors.NewInternalError(fmt.Errorf(msg)) } if err := rest.EnsureObjectNamespaceMatchesRequestNamespace(requestNamespace, clientSecretRequest); err != nil { + traceValidationFailure(tracer, err.Error()) return nil, err } // Making client secrets outside the supervisor's namespace does not make sense. if requestNamespace != r.namespace { msg := fmt.Sprintf("namespace must be %s on OIDCClientSecretRequest, was %s", r.namespace, requestNamespace) - traceValidationFailure(t, msg) + traceValidationFailure(tracer, msg) return nil, apierrors.NewBadRequest(msg) } @@ -250,13 +253,14 @@ func (r *REST) validateRequest( }, field.NewPath("metadata"), ); len(errs) > 0 { + traceValidationFailure(tracer, errs.ToAggregate().Error()) return nil, apierrors.NewInvalid(kindFromContext(ctx), clientSecretRequest.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") + traceValidationFailure(tracer, "dryRun not supported") errs := field.ErrorList{field.NotSupported(field.NewPath("dryRun"), options.DryRun, nil)} return nil, apierrors.NewInvalid(kindFromContext(ctx), clientSecretRequest.Name, errs) } @@ -264,7 +268,7 @@ func (r *REST) validateRequest( if createValidation != nil { if err := createValidation(ctx, obj.DeepCopyObject()); err != nil { - traceFailureWithError(t, "validation webhook", err) + traceFailureWithError(tracer, "validation webhook", err) return nil, err } } @@ -272,13 +276,17 @@ func (r *REST) validateRequest( return clientSecretRequest, nil } -func traceValidationFailure(t *trace.Trace, msg string) { +func traceFailure(t *trace.Trace, failureType string, msg string) { t.Step("failure", - trace.Field{Key: "failureType", Value: "request validation"}, + trace.Field{Key: "failureType", Value: failureType}, trace.Field{Key: "msg", Value: msg}, ) } +func traceValidationFailure(t *trace.Trace, msg string) { + traceFailure(t, "request validation", msg) +} + func traceFailureWithError(t *trace.Trace, failureType string, err error) { t.Step("failure", trace.Field{Key: "failureType", Value: failureType}, diff --git a/internal/registry/clientsecretrequest/rest_test.go b/internal/registry/clientsecretrequest/rest_test.go index 8928ef7f..70181f62 100644 --- a/internal/registry/clientsecretrequest/rest_test.go +++ b/internal/registry/clientsecretrequest/rest_test.go @@ -4,8 +4,10 @@ package clientsecretrequest import ( + "bytes" "context" "encoding/hex" + "encoding/json" "errors" "fmt" "io" @@ -24,11 +26,13 @@ import ( "k8s.io/apiserver/pkg/registry/rest" kubefake "k8s.io/client-go/kubernetes/fake" coretesting "k8s.io/client-go/testing" + "k8s.io/klog/v2" clientsecretapi "go.pinniped.dev/generated/latest/apis/supervisor/clientsecret" "go.pinniped.dev/generated/latest/apis/supervisor/config/v1alpha1" supervisorfake "go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned/fake" "go.pinniped.dev/internal/oidcclientsecretstorage" + "go.pinniped.dev/internal/plog" ) func TestNew(t *testing.T) { @@ -103,6 +107,7 @@ func TestCreate(t *testing.T) { want runtime.Object wantErrStatus *metav1.Status wantHashes *wantHashes + wantLogLines []string }{ { name: "wrong type of request object provided", @@ -119,6 +124,11 @@ func TestCreate(t *testing.T) { Reason: metav1.StatusReasonBadRequest, Code: http.StatusBadRequest, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:not an OIDCClientSecretRequest`, + `END`, + }, }, { name: "bad options for dry run", @@ -149,6 +159,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:dryRun not supported`, + `END`, + }, }, { name: "incorrect namespace on request context", @@ -167,6 +182,11 @@ func TestCreate(t *testing.T) { Reason: metav1.StatusReasonBadRequest, Code: http.StatusBadRequest, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:namespace must be some-namespace on OIDCClientSecretRequest, was wrong-namespace`, + `END`, + }, }, { name: "create validation: failure from kube api-server rest.ValidateObjectFunc", @@ -193,6 +213,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:validation webhook,msg:Internal error occurred: some-error-here`, + `END`, + }, }, { name: "create validation: no namespace on the request context", @@ -216,6 +241,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:no namespace information found in request context`, + `END`, + }, }, { name: "create validation: namespace on object does not match namespace on request", @@ -235,6 +265,11 @@ func TestCreate(t *testing.T) { Reason: metav1.StatusReasonBadRequest, Code: http.StatusBadRequest, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:the namespace of the provided object does not match the namespace sent on the request`, + `END`, + }, }, { name: "create validation: generateName is unsupported", @@ -268,6 +303,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:[metadata.generateName: Invalid value: "foo": generateName is not supported, metadata.name: Required value: name or generateName is required]`, + `END`, + }, }, { name: "create validation: name cannot exactly match client.oauth.pinniped.dev-", @@ -297,6 +337,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:metadata.name: Invalid value: "client.oauth.pinniped.dev-": must not equal 'client.oauth.pinniped.dev-'`, + `END`, + }, }, { name: "create validation: name must contain prefix client.oauth.pinniped.dev-", @@ -326,6 +371,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:metadata.name: Invalid value: "does-not-contain-the-prefix": must start with 'client.oauth.pinniped.dev-'`, + `END`, + }, }, { name: "create validation: name with invalid characters should error", @@ -355,6 +405,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:metadata.name: Invalid value: "client.oauth.pinniped.dev-contains/invalid/characters": may not contain '/'`, + `END`, + }, }, { name: "create validation: name validation may return multiple errors", @@ -395,6 +450,11 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `failureType:request validation,msg:[metadata.generateName: Invalid value: "no-generate-allowed": generateName is not supported, metadata.name: Invalid value: "multiple/errors/aggregated": must start with 'client.oauth.pinniped.dev-', metadata.name: Invalid value: "multiple/errors/aggregated": may not contain '/']`, + `END`, + }, }, { name: "oidcClient does not exist 404", @@ -424,6 +484,12 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `failureType:oidcClientsClient.Get,msg:oidcclients.config.supervisor.pinniped.dev "client.oauth.pinniped.dev-oidc-client-does-not-exist-404" not found`, + `END`, + }, }, { name: "unexpected error getting oidcClient 500", @@ -451,6 +517,12 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `failureType:oidcClientsClient.Get,msg:unexpected error darn`, + `END`, + }, }, { name: "failed to get kube secret for oidcClient", @@ -484,6 +556,13 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `failureType:secretStorage.Get,msg:failed to get client secret for uid : failed to get oidc-client-secret for signature : sadly no secrets`, + `END`, + }, }, { name: "failed to generate new client secret for oidcClient", @@ -517,6 +596,14 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `failureType:generateSecret,msg:could not generate client secret: always errors`, + `END`, + }, }, { name: "failed to generate hash for new client secret for oidcClient", @@ -552,6 +639,15 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `failureType:bcrypt.GenerateFromPassword,msg:can't hash stuff`, + `END`, + }, }, { name: "happy path: no secrets exist, create secret and hash for found oidcclient", @@ -587,6 +683,16 @@ func TestCreate(t *testing.T) { fakeBcryptRandomBytes, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `secretStorage.Set`, + `END`, + }, }, { name: "happy path: secret exists, prepend new secret hash to secret to the list of hashes for found oidcclient", @@ -637,6 +743,16 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 3, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `secretStorage.Set`, + `END`, + }, }, { name: "happy path: secret exists, append new secret hash to secret and revoke old for found oidcclient", @@ -684,6 +800,16 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 1, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `secretStorage.Set`, + `END`, + }, }, { name: "happy path: secret exists, revoke old secrets but retain latest for found oidcclient", @@ -731,6 +857,14 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 1, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `secretStorage.Set`, + `END`, + }, }, { name: "secret exists but oidcclient secret has too many hashes, fails to create when RevokeOldSecrets:false (max 5), secret is not updated", @@ -785,6 +919,16 @@ func TestCreate(t *testing.T) { Reason: metav1.StatusReasonBadRequest, Code: http.StatusBadRequest, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `failureType:secretStorage.Set,msg:OIDCClient client.oauth.pinniped.dev-some-client has too many secrets, spec.revokeOldSecrets must be true`, + `END`, + }, }, { name: "secret exists but oidcclient secret has too many hashes, fails to create when RevokeOldSecrets:false (greater than 5), secret is not updated", @@ -841,6 +985,16 @@ func TestCreate(t *testing.T) { Reason: metav1.StatusReasonBadRequest, Code: http.StatusBadRequest, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `failureType:secretStorage.Set,msg:OIDCClient client.oauth.pinniped.dev-some-client has too many secrets, spec.revokeOldSecrets must be true`, + `END`, + }, }, { name: "attempted to create storage secret because it did not initially exist but was created by someone else while generating new client secret & hash", @@ -881,6 +1035,16 @@ func TestCreate(t *testing.T) { Name: "client.oauth.pinniped.dev-some-client", }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `failureType:secretStorage.Set,msg:failed to create client secret for uid 12345: failed to create oidc-client-secret for signature MTIzNDU: secrets "pinniped-storage-oidc-client-secret-gezdgnbv" already exists`, + `END`, + }, }, { name: "attempted to create storage secret because it did not initially exist but received a conflict error", @@ -925,6 +1089,16 @@ func TestCreate(t *testing.T) { Name: "client.oauth.pinniped.dev-some-client", }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `failureType:secretStorage.Set,msg:failed to create client secret for uid 12345: failed to create oidc-client-secret for signature MTIzNDU: Operation cannot be fulfilled on secrets "pinniped-storage-oidc-client-secret-gezdgnbv": something deeply conflicted`, + `END`, + }, }, { name: "attempted to create storage secret but received an unknown error", @@ -963,6 +1137,16 @@ func TestCreate(t *testing.T) { }}, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `failureType:secretStorage.Set,msg:failed to create client secret for uid 12345: failed to create oidc-client-secret for signature MTIzNDU: some random error`, + `END`, + }, }, { name: "happy path noop: do not create a new secret, revoke old secrets, but there is no existing storage secret", @@ -991,6 +1175,13 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 0, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `END`, + }, }, { name: "happy path noop: do not create a new secret, revoke old secrets, but there is no existing storage secret", @@ -1019,6 +1210,13 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 0, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `END`, + }, }, { name: "happy path noop: do not create a new secret, revoke old secrets, and there is an existing storage secret", @@ -1067,6 +1265,13 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 2, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `END`, + }, }, { name: "happy path: generate new secret and revoking old secret when there was a single secret hash to start with", @@ -1113,6 +1318,16 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 1, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `secretStorage.Set`, + `END`, + }, }, { name: "happy path: generate new secret when existing secrets is max (5)", @@ -1163,6 +1378,16 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 1, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `secretStorage.Set`, + `END`, + }, }, { name: "happy path: generate new secret when existing secrets exceeds maximum (5)", @@ -1214,12 +1439,28 @@ func TestCreate(t *testing.T) { TotalClientSecrets: 1, }, }, + wantLogLines: []string{ + `"create"`, + `"validateRequest"`, + `oidcClientsClient.Get`, + `secretStorage.Get`, + `generateSecret`, + `bcrypt.GenerateFromPassword`, + `secretStorage.Set`, + `END`, + }, }, } for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { - t.Parallel() + // t.Parallel() should not be used because we are mutating the global logger. + var log bytes.Buffer + logger := plog.TestZapr(t, &log) + klog.SetLogger(logger) + t.Cleanup(func() { + klog.ClearLogger() + }) kubeClient := kubefake.NewSimpleClientset() secretsClient := kubeClient.CoreV1().Secrets(namespace) @@ -1297,6 +1538,8 @@ func TestCreate(t *testing.T) { require.NoError(t, err) require.Empty(t, secrets.Items) } + + requireLogLinesContain(t, log.String(), tt.wantLogLines) }) } } @@ -1306,3 +1549,22 @@ type readerAlwaysErrors struct{} func (r readerAlwaysErrors) Read(p []byte) (n int, err error) { return 0, errors.New("always errors") } + +func requireLogLinesContain(t *testing.T, fullLog string, wantLines []string) { + if len(wantLines) == 0 { + require.Empty(t, fullLog) + return + } + var jsonLog map[string]interface{} + err := json.Unmarshal([]byte(fullLog), &jsonLog) + require.NoError(t, err) + require.Contains(t, jsonLog, "message") + message := jsonLog["message"] + require.IsType(t, "type of string", message) + lines := strings.Split(strings.TrimSpace(message.(string)), "\n") + + require.Lenf(t, lines, len(wantLines), "actual log lines length should match expected length, actual lines:\n\n%s", strings.Join(lines, "\n")) + for i := range wantLines { + require.Containsf(t, lines[i], wantLines[i], "log line at index %d should have contained expected output", i) + } +}