Merge pull request #119166 from nilekhc/log-decryption-failure

feat: improves metric and logging

staging/src/k8s.io/apiserver/pkg/storage/value/metrics.go

@@ -61,7 +61,7 @@ var (
 			Namespace:      namespace,
 			Subsystem:      subsystem,
 			Name:           "transformation_operations_total",
-			Help:           "Total number of transformations.",
+			Help:           "Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption",
 			StabilityLevel: metrics.ALPHA,
 		},
 		[]string{"transformation_type", "transformer_prefix", "status"},

staging/src/k8s.io/apiserver/pkg/storage/value/metrics_test.go

@@ -56,7 +56,7 @@ func TestTotals(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
 				# TYPE apiserver_storage_transformation_operations_total counter
 				apiserver_storage_transformation_operations_total{status="unknown-non-grpc",transformation_type="from_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
 				apiserver_storage_transformation_operations_total{status="unknown-non-grpc",transformation_type="to_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
@@ -69,7 +69,7 @@ func TestTotals(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
 				# TYPE apiserver_storage_transformation_operations_total counter
 				apiserver_storage_transformation_operations_total{status="OK",transformation_type="from_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
 				apiserver_storage_transformation_operations_total{status="OK",transformation_type="to_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
@@ -82,7 +82,7 @@ func TestTotals(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
 				# TYPE apiserver_storage_transformation_operations_total counter
 				apiserver_storage_transformation_operations_total{status="FailedPrecondition",transformation_type="from_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
 				apiserver_storage_transformation_operations_total{status="FailedPrecondition",transformation_type="to_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
@@ -95,7 +95,7 @@ func TestTotals(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+				# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
 				# TYPE apiserver_storage_transformation_operations_total counter
 				apiserver_storage_transformation_operations_total{status="Internal",transformation_type="from_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
 				apiserver_storage_transformation_operations_total{status="Internal",transformation_type="to_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
@@ -108,7 +108,7 @@ func TestTotals(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-			# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+			# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
 			# TYPE apiserver_storage_transformation_operations_total counter
 			apiserver_storage_transformation_operations_total{status="NotFound",transformation_type="from_storage",transformer_prefix="k8s:enc:kms:v1:"} 1
 			apiserver_storage_transformation_operations_total{status="NotFound",transformation_type="to_storage",transformer_prefix="k8s:enc:kms:v1:"} 1

staging/src/k8s.io/apiserver/pkg/storage/value/transformer.go

@@ -25,6 +25,8 @@ import (
 
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/apimachinery/pkg/util/errors"
+	genericapirequest "k8s.io/apiserver/pkg/endpoints/request"
+	"k8s.io/klog/v2"
 )
 
 func init() {
@@ -158,6 +160,7 @@ func (t *prefixTransformers) TransformFromStorage(ctx context.Context, data []by
 		}
 	}
 	if err := errors.Reduce(errors.NewAggregate(errs)); err != nil {
+		logTransformErr(ctx, err, "failed to decrypt data")
 		return nil, false, err
 	}
 	RecordTransformation("from_storage", "unknown", time.Since(start), t.err)
@@ -171,6 +174,7 @@ func (t *prefixTransformers) TransformToStorage(ctx context.Context, data []byte
 	result, err := transformer.Transformer.TransformToStorage(ctx, data, dataCtx)
 	RecordTransformation("to_storage", string(transformer.Prefix), time.Since(start), err)
 	if err != nil {
+		logTransformErr(ctx, err, "failed to encrypt data")
 		return nil, err
 	}
 	prefixedData := make([]byte, len(transformer.Prefix), len(result)+len(transformer.Prefix))
@@ -178,3 +182,32 @@ func (t *prefixTransformers) TransformToStorage(ctx context.Context, data []byte
 	prefixedData = append(prefixedData, result...)
 	return prefixedData, nil
 }
+
+func logTransformErr(ctx context.Context, err error, message string) {
+	requestInfo := getRequestInfoFromContext(ctx)
+	if klogLevel6 := klog.V(6); klogLevel6.Enabled() {
+		klogLevel6.InfoSDepth(
+			1,
+			message,
+			"err", err,
+			"group", requestInfo.APIGroup,
+			"version", requestInfo.APIVersion,
+			"resource", requestInfo.Resource,
+			"subresource", requestInfo.Subresource,
+			"verb", requestInfo.Verb,
+			"namespace", requestInfo.Namespace,
+			"name", requestInfo.Name,
+		)
+
+		return
+	}
+
+	klog.ErrorSDepth(1, err, message)
+}
+
+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/transformer_test.go

@@ -19,12 +19,17 @@ package value
 import (
 	"bytes"
 	"context"
+	"errors"
+	"flag"
 	"fmt"
+	"regexp"
 	"strings"
 	"testing"
 
+	genericapirequest "k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/component-base/metrics/legacyregistry"
 	"k8s.io/component-base/metrics/testutil"
+	"k8s.io/klog/v2"
 )
 
 type testTransformer struct {
@@ -129,7 +134,7 @@ func TestPrefixFromMetrics(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
   # TYPE apiserver_storage_transformation_operations_total counter
   apiserver_storage_transformation_operations_total{status="OK",transformation_type="from_storage",transformer_prefix="identity"} 1
   `,
@@ -143,7 +148,7 @@ func TestPrefixFromMetrics(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
   # TYPE apiserver_storage_transformation_operations_total counter
   apiserver_storage_transformation_operations_total{status="OK",transformation_type="from_storage",transformer_prefix="other:"} 1
   `,
@@ -157,7 +162,7 @@ func TestPrefixFromMetrics(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
   # TYPE apiserver_storage_transformation_operations_total counter
   apiserver_storage_transformation_operations_total{status="unknown-non-grpc",transformation_type="from_storage",transformer_prefix="other:"} 1
   `,
@@ -171,7 +176,7 @@ func TestPrefixFromMetrics(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
   # TYPE apiserver_storage_transformation_operations_total counter
   apiserver_storage_transformation_operations_total{status="unknown-non-grpc",transformation_type="from_storage",transformer_prefix="unknown"} 1
   `,
@@ -215,7 +220,7 @@ func TestPrefixToMetrics(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
   # TYPE apiserver_storage_transformation_operations_total counter
   apiserver_storage_transformation_operations_total{status="OK",transformation_type="to_storage",transformer_prefix="other:"} 1
   `,
@@ -229,7 +234,7 @@ func TestPrefixToMetrics(t *testing.T) {
 				"apiserver_storage_transformation_operations_total",
 			},
 			want: `
-	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations.
+	# HELP apiserver_storage_transformation_operations_total [ALPHA] Total number of transformations. Successful transformation will have a status 'OK' and a varied status string when the transformation fails. This status and transformation_type fields may be used for alerting on encryption/decryption failure using transformation_type from_storage for decryption and to_storage for encryption
   # TYPE apiserver_storage_transformation_operations_total counter
   apiserver_storage_transformation_operations_total{status="unknown-non-grpc",transformation_type="to_storage",transformer_prefix="other:"} 1
   `,
@@ -250,3 +255,63 @@ func TestPrefixToMetrics(t *testing.T) {
 		})
 	}
 }
+
+func TestLogTransformErr(t *testing.T) {
+	klog.InitFlags(nil)
+	tests := []struct {
+		name        string
+		ctx         context.Context
+		err         error
+		message     string
+		expectedLog string
+	}{
+		{
+			name: "log error with request info",
+			ctx: genericapirequest.WithRequestInfo(testContext(t), &genericapirequest.RequestInfo{
+				APIGroup:    "awesome.bears.com",
+				APIVersion:  "v1",
+				Resource:    "pandas",
+				Subresource: "status",
+				Namespace:   "kube-system",
+				Name:        "panda",
+				Verb:        "update",
+			}),
+			err:         errors.New("encryption failed"),
+			message:     "failed to encrypt data",
+			expectedLog: "\"failed to encrypt data\" err=\"encryption failed\" group=\"awesome.bears.com\" version=\"v1\" resource=\"pandas\" subresource=\"status\" verb=\"update\" namespace=\"kube-system\" name=\"panda\"\n",
+		},
+		{
+			name:        "log error without request info",
+			ctx:         context.Background(),
+			err:         errors.New("decryption failed"),
+			message:     "failed to decrypt data",
+			expectedLog: "\"failed to decrypt data\" err=\"decryption failed\" group=\"\" version=\"\" resource=\"\" subresource=\"\" verb=\"\" namespace=\"\" name=\"\"\n",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var buf bytes.Buffer
+			flag.Set("v", "6")
+			flag.Parse()
+			klog.SetOutput(&buf)
+			klog.LogToStderr(false)
+			defer klog.LogToStderr(true)
+
+			logTransformErr(tt.ctx, tt.err, tt.message)
+
+			// remove timestamp and goroutine id from log message to make it easier to compare
+			gotLog := regexp.MustCompile(`\w+ \d+:\d+:\d+\.\d+.*\d+.*transformer_test.go:\d+].`).ReplaceAllString(buf.String(), "")
+
+			if gotLog != tt.expectedLog {
+				t.Errorf("expected log message %q, got %q", tt.expectedLog, gotLog)
+			}
+		})
+	}
+}
+
+func testContext(t *testing.T) context.Context {
+	ctx, cancel := context.WithCancel(context.Background())
+	t.Cleanup(cancel)
+	return ctx
+}