[KMSv2] log request metadata as part of read/write

Signed-off-by: Anish Ramasekar <anish.ramasekar@gmail.com>

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

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