From e40b3cf54eb2feee738da73bdf1de40bd5cba441 Mon Sep 17 00:00:00 2001 From: Anish Ramasekar Date: Fri, 24 Feb 2023 23:06:30 +0000 Subject: [PATCH] [KMSv2] log request metadata as part of read/write Signed-off-by: Anish Ramasekar --- .../value/encrypt/envelope/kmsv2/envelope.go | 19 +++- .../encrypt/envelope/kmsv2/envelope_test.go | 91 +++++++++++++++++++ 2 files changed, 108 insertions(+), 2 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope.go b/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope.go index ae37f178b9e..18437bf0b4f 100644 --- a/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope.go +++ b/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope.go @@ -30,6 +30,7 @@ import ( "k8s.io/apimachinery/pkg/util/uuid" "k8s.io/apimachinery/pkg/util/validation" "k8s.io/apimachinery/pkg/util/validation/field" + genericapirequest "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/apiserver/pkg/storage/value" kmstypes "k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/v2alpha1" "k8s.io/apiserver/pkg/storage/value/encrypt/envelope/metrics" @@ -109,8 +110,12 @@ func (t *envelopeTransformer) TransformFromStorage(ctx context.Context, data []b if transformer == nil { value.RecordCacheMiss() + requestInfo := getRequestInfoFromContext(ctx) uid := string(uuid.NewUUID()) - klog.V(6).InfoS("Decrypting content using envelope service", "uid", uid, "key", string(dataCtx.AuthenticatedData())) + klog.V(6).InfoS("decrypting content using envelope service", "uid", uid, "key", string(dataCtx.AuthenticatedData()), + "group", requestInfo.APIGroup, "version", requestInfo.APIVersion, "resource", requestInfo.Resource, "subresource", requestInfo.Subresource, + "verb", requestInfo.Verb, "namespace", requestInfo.Namespace, "name", requestInfo.Name) + key, err := t.envelopeService.Decrypt(ctx, uid, &kmsservice.DecryptRequest{ Ciphertext: encryptedObject.EncryptedDEK, KeyID: encryptedObject.KeyID, @@ -154,8 +159,11 @@ func (t *envelopeTransformer) TransformToStorage(ctx context.Context, data []byt return nil, err } + requestInfo := getRequestInfoFromContext(ctx) uid := string(uuid.NewUUID()) - klog.V(6).InfoS("encrypting content using envelope service", "uid", uid, "key", string(dataCtx.AuthenticatedData())) + klog.V(6).InfoS("encrypting content using envelope service", "uid", uid, "key", string(dataCtx.AuthenticatedData()), + "group", requestInfo.APIGroup, "version", requestInfo.APIVersion, "resource", requestInfo.Resource, "subresource", requestInfo.Subresource, + "verb", requestInfo.Verb, "namespace", requestInfo.Namespace, "name", requestInfo.Name) resp, err := t.envelopeService.Encrypt(ctx, uid, newKey) if err != nil { return nil, fmt.Errorf("failed to encrypt DEK, error: %w", err) @@ -304,3 +312,10 @@ func ValidateKeyID(keyID string) (ErrCodeKeyID, error) { } return errKeyIDOKCode, nil } + +func getRequestInfoFromContext(ctx context.Context) *genericapirequest.RequestInfo { + if reqInfo, found := genericapirequest.RequestInfoFrom(ctx); found { + return reqInfo + } + return &genericapirequest.RequestInfo{} +} diff --git a/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope_test.go b/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope_test.go index 49e0370e755..1e20369fe2f 100644 --- a/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope_test.go +++ b/staging/src/k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/envelope_test.go @@ -21,19 +21,23 @@ import ( "bytes" "context" "encoding/base64" + "flag" "fmt" "reflect" + "regexp" "strconv" "strings" "testing" "time" + genericapirequest "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/apiserver/pkg/storage/value" aestransformer "k8s.io/apiserver/pkg/storage/value/encrypt/aes" kmstypes "k8s.io/apiserver/pkg/storage/value/encrypt/envelope/kmsv2/v2alpha1" "k8s.io/apiserver/pkg/storage/value/encrypt/envelope/metrics" "k8s.io/component-base/metrics/legacyregistry" "k8s.io/component-base/metrics/testutil" + "k8s.io/klog/v2" kmsservice "k8s.io/kms/pkg/service" testingclock "k8s.io/utils/clock/testing" ) @@ -661,3 +665,90 @@ func TestEnvelopeMetrics(t *testing.T) { }) } } + +func TestEnvelopeLogging(t *testing.T) { + klog.InitFlags(nil) + flag.Set("v", "6") + flag.Parse() + + testCases := []struct { + desc string + ctx context.Context + wantLogs []string + }{ + { + desc: "no request info in context", + ctx: testContext(t), + wantLogs: []string{ + `"encrypting content using envelope service" uid="UID" key="0123456789" group="" version="" resource="" subresource="" verb="" namespace="" name=""`, + `"decrypting content using envelope service" uid="UID" key="0123456789" group="" version="" resource="" subresource="" verb="" namespace="" name=""`, + }, + }, + { + desc: "request info in context", + ctx: genericapirequest.WithRequestInfo(testContext(t), &genericapirequest.RequestInfo{ + APIGroup: "awesome.bears.com", + APIVersion: "v1", + Resource: "pandas", + Subresource: "status", + Namespace: "kube-system", + Name: "panda", + Verb: "update", + }), + wantLogs: []string{ + `"encrypting content using envelope service" uid="UID" key="0123456789" group="awesome.bears.com" version="v1" resource="pandas" subresource="status" verb="update" namespace="kube-system" name="panda"`, + `"decrypting content using envelope service" uid="UID" key="0123456789" group="awesome.bears.com" version="v1" resource="pandas" subresource="status" verb="update" namespace="kube-system" name="panda"`, + }, + }, + } + + for _, tc := range testCases { + tc := tc + t.Run(tc.desc, func(t *testing.T) { + var buf bytes.Buffer + klog.SetOutput(&buf) + klog.LogToStderr(false) + defer klog.LogToStderr(true) + + envelopeService := newTestEnvelopeService() + fakeClock := testingclock.NewFakeClock(time.Now()) + envelopeTransformer := newEnvelopeTransformerWithClock(envelopeService, testProviderName, + func(ctx context.Context) (string, error) { + return "1", nil + }, + func(ctx context.Context) error { + return nil + }, + aestransformer.NewGCMTransformer, 1*time.Second, fakeClock) + + dataCtx := value.DefaultContext([]byte(testContextText)) + originalText := []byte(testText) + + transformedData, err := envelopeTransformer.TransformToStorage(tc.ctx, originalText, dataCtx) + if err != nil { + t.Fatalf("envelopeTransformer: error while transforming data to storage: %v", err) + } + + // advance the clock to trigger cache to expire, so we make a decrypt call that will log + fakeClock.Step(2 * time.Second) + + _, _, err = envelopeTransformer.TransformFromStorage(tc.ctx, transformedData, dataCtx) + if err != nil { + t.Fatalf("could not decrypt Envelope transformer's encrypted data even once: %v", err) + } + + klog.Flush() + klog.SetOutput(&bytes.Buffer{}) // prevent further writes into buf + capturedOutput := buf.String() + + // replace the uid with a constant to make the test output stable and assertable + capturedOutput = regexp.MustCompile(`uid="[^"]+"`).ReplaceAllString(capturedOutput, `uid="UID"`) + + for _, wantLog := range tc.wantLogs { + if !strings.Contains(capturedOutput, wantLog) { + t.Errorf("expected log %q, got %q", wantLog, capturedOutput) + } + } + }) + } +}