Don't add audit annotations directly to the audit event

Kubernetes-commit: bdebc62d49293a0fbbd7e0d95bfd94b1ce21015c

pkg/admission/audit.go

@@ -19,19 +19,13 @@ package admission
 import (
 	"context"
 	"fmt"
-	"sync"
 
-	auditinternal "k8s.io/apiserver/pkg/apis/audit"
 	"k8s.io/apiserver/pkg/audit"
 )
 
 // auditHandler logs annotations set by other admission handlers
 type auditHandler struct {
 	Interface
-	// TODO: move the lock near the Annotations field of the audit event so it is always protected from concurrent access.
-	// to protect the 'Annotations' map of the audit event from concurrent writes
-	mutex sync.Mutex
-	ae    *auditinternal.Event
 }
 
 var _ Interface = &auditHandler{}
@@ -42,11 +36,11 @@ var _ ValidationInterface = &auditHandler{}
 // of attribute into the audit event. Attributes passed to the Admit and
 // Validate function must be instance of privateAnnotationsGetter or
 // AnnotationsGetter, otherwise an error is returned.
-func WithAudit(i Interface, ae *auditinternal.Event) Interface {
-	if i == nil || ae == nil {
+func WithAudit(i Interface) Interface {
+	if i == nil {
 		return i
 	}
-	return &auditHandler{Interface: i, ae: ae}
+	return &auditHandler{Interface: i}
 }
 
 func (handler *auditHandler) Admit(ctx context.Context, a Attributes, o ObjectInterfaces) error {
@@ -59,7 +53,7 @@ func (handler *auditHandler) Admit(ctx context.Context, a Attributes, o ObjectIn
 	var err error
 	if mutator, ok := handler.Interface.(MutationInterface); ok {
 		err = mutator.Admit(ctx, a, o)
-		handler.logAnnotations(a)
+		handler.logAnnotations(ctx, a)
 	}
 	return err
 }
@@ -74,7 +68,7 @@ func (handler *auditHandler) Validate(ctx context.Context, a Attributes, o Objec
 	var err error
 	if validator, ok := handler.Interface.(ValidationInterface); ok {
 		err = validator.Validate(ctx, a, o)
-		handler.logAnnotations(a)
+		handler.logAnnotations(ctx, a)
 	}
 	return err
 }
@@ -88,23 +82,21 @@ func ensureAnnotationGetter(a Attributes) error {
 	return fmt.Errorf("attributes must be an instance of privateAnnotationsGetter or AnnotationsGetter")
 }
 
-func (handler *auditHandler) logAnnotations(a Attributes) {
-	if handler.ae == nil {
+func (handler *auditHandler) logAnnotations(ctx context.Context, a Attributes) {
+	ae := audit.AuditEventFrom(ctx)
+	if ae == nil {
 		return
 	}
-	handler.mutex.Lock()
-	defer handler.mutex.Unlock()
 
+	var annotations map[string]string
 	switch a := a.(type) {
 	case privateAnnotationsGetter:
-		for key, value := range a.getAnnotations(handler.ae.Level) {
-			audit.LogAnnotation(handler.ae, key, value)
-		}
+		annotations = a.getAnnotations(ae.Level)
 	case AnnotationsGetter:
-		for key, value := range a.GetAnnotations(handler.ae.Level) {
-			audit.LogAnnotation(handler.ae, key, value)
-		}
+		annotations = a.GetAnnotations(ae.Level)
 	default:
 		// this will never happen, because we have already checked it in ensureAnnotationGetter
 	}
+
+	audit.AddAuditAnnotationsMap(ctx, annotations)
 }

pkg/admission/audit_test.go

@@ -24,6 +24,7 @@ import (
 
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	auditinternal "k8s.io/apiserver/pkg/apis/audit"
+	"k8s.io/apiserver/pkg/audit"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -142,7 +143,8 @@ func TestWithAudit(t *testing.T) {
 	for tcName, tc := range testCases {
 		var handler Interface = fakeHandler{tc.admit, tc.admitAnnotations, tc.validate, tc.validateAnnotations, tc.handles}
 		ae := &auditinternal.Event{Level: auditinternal.LevelMetadata}
-		auditHandler := WithAudit(handler, ae)
+		ctx := audit.WithAuditContext(context.Background(), &audit.AuditContext{Event: ae})
+		auditHandler := WithAudit(handler)
 		a := attributes()
 
 		assert.Equal(t, handler.Handles(Create), auditHandler.Handles(Create), tcName+": WithAudit decorator should not effect the return value")
@@ -151,13 +153,13 @@ func TestWithAudit(t *testing.T) {
 		require.True(t, ok)
 		auditMutator, ok := auditHandler.(MutationInterface)
 		require.True(t, ok)
-		assert.Equal(t, mutator.Admit(context.TODO(), a, nil), auditMutator.Admit(context.TODO(), a, nil), tcName+": WithAudit decorator should not effect the return value")
+		assert.Equal(t, mutator.Admit(ctx, a, nil), auditMutator.Admit(ctx, a, nil), tcName+": WithAudit decorator should not effect the return value")
 
 		validator, ok := handler.(ValidationInterface)
 		require.True(t, ok)
 		auditValidator, ok := auditHandler.(ValidationInterface)
 		require.True(t, ok)
-		assert.Equal(t, validator.Validate(context.TODO(), a, nil), auditValidator.Validate(context.TODO(), a, nil), tcName+": WithAudit decorator should not effect the return value")
+		assert.Equal(t, validator.Validate(ctx, a, nil), auditValidator.Validate(ctx, a, nil), tcName+": WithAudit decorator should not effect the return value")
 
 		annotations := make(map[string]string, len(tc.admitAnnotations)+len(tc.validateAnnotations))
 		for k, v := range tc.admitAnnotations {
@@ -183,7 +185,8 @@ func TestWithAuditConcurrency(t *testing.T) {
 	}
 	var handler Interface = fakeHandler{admitAnnotations: admitAnnotations, handles: true}
 	ae := &auditinternal.Event{Level: auditinternal.LevelMetadata}
-	auditHandler := WithAudit(handler, ae)
+	ctx := audit.WithAuditContext(context.Background(), &audit.AuditContext{Event: ae})
+	auditHandler := WithAudit(handler)
 	a := attributes()
 
 	// Simulate the scenario store.DeleteCollection
@@ -197,7 +200,7 @@ func TestWithAuditConcurrency(t *testing.T) {
 			require.True(t, ok)
 			auditMutator, ok := auditHandler.(MutationInterface)
 			require.True(t, ok)
-			assert.Equal(t, mutator.Admit(context.TODO(), a, nil), auditMutator.Admit(context.TODO(), a, nil), "WithAudit decorator should not effect the return value")
+			assert.Equal(t, mutator.Admit(ctx, a, nil), auditMutator.Admit(ctx, a, nil), "WithAudit decorator should not effect the return value")
 		}()
 	}
 	wg.Wait()

pkg/audit/context.go

@@ -18,6 +18,7 @@ package audit
 
 import (
 	"context"
+	"fmt"
 	"sync"
 
 	auditinternal "k8s.io/apiserver/pkg/apis/audit"
@@ -30,10 +31,7 @@ type key int
 
 const (
 	// auditAnnotationsKey is the context key for the audit annotations.
-	// TODO: it's wasteful to store the audit annotations under a separate key, we
-	//  copy the request context twice for audit purposes. We should move the audit
-	//  annotations under AuditContext so we can get rid of the additional request
-	//  context copy.
+	// TODO: consolidate all audit info under the AuditContext, rather than storing 3 separate keys.
 	auditAnnotationsKey key = iota
 
 	// auditKey is the context key for storing the audit event that is being
@@ -75,25 +73,80 @@ func WithAuditAnnotations(parent context.Context) context.Context {
 func AddAuditAnnotation(ctx context.Context, key, value string) {
 	mutex, ok := auditAnnotationsMutex(ctx)
 	if !ok {
-		klog.Errorf("Attempted to add audit annotation from unsupported request chain: %q=%q", key, value)
+		klog.ErrorS(nil, "Attempted to add audit annotations from unsupported request chain", "annotation", fmt.Sprintf("%s=%s", key, value))
 		return
 	}
 
 	mutex.Lock()
 	defer mutex.Unlock()
 
-	// use the audit event directly if we have it
-	if ae := AuditEventFrom(ctx); ae != nil {
-		LogAnnotation(ae, key, value)
+	ae := AuditEventFrom(ctx)
+	var ctxAnnotations *[]annotation
+	if ae == nil {
+		ctxAnnotations, _ = ctx.Value(auditAnnotationsKey).(*[]annotation)
+	}
+
+	addAuditAnnotationLocked(ae, ctxAnnotations, key, value)
+}
+
+// AddAuditAnnotations is a bulk version of AddAuditAnnotation. Refer to AddAuditAnnotation for
+// restrictions on when this can be called.
+// keysAndValues are the key-value pairs to add, and must have an even number of items.
+func AddAuditAnnotations(ctx context.Context, keysAndValues ...string) {
+	mutex, ok := auditAnnotationsMutex(ctx)
+	if !ok {
+		klog.ErrorS(nil, "Attempted to add audit annotations from unsupported request chain", "annotations", keysAndValues)
 		return
 	}
 
-	annotations, ok := ctx.Value(auditAnnotationsKey).(*[]annotation)
+	mutex.Lock()
+	defer mutex.Unlock()
+
+	ae := AuditEventFrom(ctx)
+	var ctxAnnotations *[]annotation
+	if ae == nil {
+		ctxAnnotations, _ = ctx.Value(auditAnnotationsKey).(*[]annotation)
+	}
+
+	if len(keysAndValues)%2 != 0 {
+		klog.Errorf("Dropping mismatched audit annotation %q", keysAndValues[len(keysAndValues)-1])
+	}
+	for i := 0; i < len(keysAndValues); i += 2 {
+		addAuditAnnotationLocked(ae, ctxAnnotations, keysAndValues[i], keysAndValues[i+1])
+	}
+}
+
+// AddAuditAnnotationsMap is a bulk version of AddAuditAnnotation. Refer to AddAuditAnnotation for
+// restrictions on when this can be called.
+func AddAuditAnnotationsMap(ctx context.Context, annotations map[string]string) {
+	mutex, ok := auditAnnotationsMutex(ctx)
 	if !ok {
-		return // adding audit annotation is not supported at this call site
+		klog.ErrorS(nil, "Attempted to add audit annotations from unsupported request chain", "annotations", annotations)
+		return
 	}
 
-	*annotations = append(*annotations, annotation{key: key, value: value})
+	mutex.Lock()
+	defer mutex.Unlock()
+
+	ae := AuditEventFrom(ctx)
+	var ctxAnnotations *[]annotation
+	if ae == nil {
+		ctxAnnotations, _ = ctx.Value(auditAnnotationsKey).(*[]annotation)
+	}
+
+	for k, v := range annotations {
+		addAuditAnnotationLocked(ae, ctxAnnotations, k, v)
+	}
+}
+
+// addAuditAnnotationLocked is the shared code for recording an audit annotation. This method should
+// only be called while the auditAnnotationsMutex is locked.
+func addAuditAnnotationLocked(ae *auditinternal.Event, annotations *[]annotation, key, value string) {
+	if ae != nil {
+		logAnnotation(ae, key, value)
+	} else if annotations != nil {
+		*annotations = append(*annotations, annotation{key: key, value: value})
+	}
 }
 
 // This is private to prevent reads/write to the slice from outside of this package.
@@ -114,8 +167,23 @@ func addAuditAnnotationsFrom(ctx context.Context, ev *auditinternal.Event) {
 	}
 
 	for _, kv := range *annotations {
-		LogAnnotation(ev, kv.key, kv.value)
+		logAnnotation(ev, kv.key, kv.value)
+	}
+}
+
+// LogAnnotation fills in the Annotations according to the key value pair.
+func logAnnotation(ae *auditinternal.Event, key, value string) {
+	if ae == nil || ae.Level.Less(auditinternal.LevelMetadata) {
+		return
+	}
+	if ae.Annotations == nil {
+		ae.Annotations = make(map[string]string)
+	}
+	if v, ok := ae.Annotations[key]; ok && v != value {
+		klog.Warningf("Failed to set annotations[%q] to %q for audit:%q, it has already been set to %q", key, value, ae.AuditID, ae.Annotations[key])
+		return
 	}
+	ae.Annotations[key] = value
 }
 
 // WithAuditContext returns a new context that stores the pair of the audit

pkg/audit/context_test.go

@@ -97,6 +97,20 @@ func TestAddAuditAnnotation(t *testing.T) {
 	}
 }
 
+func TestLogAnnotation(t *testing.T) {
+	ev := &auditinternal.Event{
+		Level:   auditinternal.LevelMetadata,
+		AuditID: "fake id",
+	}
+	logAnnotation(ev, "foo", "bar")
+	logAnnotation(ev, "foo", "baz")
+	assert.Equal(t, "bar", ev.Annotations["foo"], "audit annotation should not be overwritten.")
+
+	logAnnotation(ev, "qux", "")
+	logAnnotation(ev, "qux", "baz")
+	assert.Equal(t, "", ev.Annotations["qux"], "audit annotation should not be overwritten.")
+}
+
 func newAuditContext(l auditinternal.Level) *AuditContext {
 	return &AuditContext{
 		Event: &auditinternal.Event{

pkg/audit/request.go

@@ -243,21 +243,6 @@ func encodeObject(obj runtime.Object, gv schema.GroupVersion, serializer runtime
 	}, nil
 }
 
-// LogAnnotation fills in the Annotations according to the key value pair.
-func LogAnnotation(ae *auditinternal.Event, key, value string) {
-	if ae == nil || ae.Level.Less(auditinternal.LevelMetadata) {
-		return
-	}
-	if ae.Annotations == nil {
-		ae.Annotations = make(map[string]string)
-	}
-	if v, ok := ae.Annotations[key]; ok && v != value {
-		klog.Warningf("Failed to set annotations[%q] to %q for audit:%q, it has already been set to %q", key, value, ae.AuditID, ae.Annotations[key])
-		return
-	}
-	ae.Annotations[key] = value
-}
-
 // truncate User-Agent if too long, otherwise return it directly.
 func maybeTruncateUserAgent(req *http.Request) string {
 	ua := req.UserAgent()

pkg/audit/request_test.go

@@ -25,26 +25,11 @@ import (
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
-	auditinternal "k8s.io/apiserver/pkg/apis/audit"
 
 	"github.com/google/go-cmp/cmp"
 	"github.com/stretchr/testify/assert"
 )
 
-func TestLogAnnotation(t *testing.T) {
-	ev := &auditinternal.Event{
-		Level:   auditinternal.LevelMetadata,
-		AuditID: "fake id",
-	}
-	LogAnnotation(ev, "foo", "bar")
-	LogAnnotation(ev, "foo", "baz")
-	assert.Equal(t, "bar", ev.Annotations["foo"], "audit annotation should not be overwritten.")
-
-	LogAnnotation(ev, "qux", "")
-	LogAnnotation(ev, "qux", "baz")
-	assert.Equal(t, "", ev.Annotations["qux"], "audit annotation should not be overwritten.")
-}
-
 func TestMaybeTruncateUserAgent(t *testing.T) {
 	req := &http.Request{}
 	req.Header = http.Header{}

pkg/endpoints/filters/audit.go

@@ -177,10 +177,8 @@ func writeLatencyToAnnotation(ctx context.Context, ev *auditinternal.Event) {
 	}
 
 	// record the total latency for this request, for convenience.
-	audit.LogAnnotation(ev, "apiserver.latency.k8s.io/total", latency.String())
-	for k, v := range layerLatencies {
-		audit.LogAnnotation(ev, k, v)
-	}
+	layerLatencies["apiserver.latency.k8s.io/total"] = latency.String()
+	audit.AddAuditAnnotationsMap(ctx, layerLatencies)
 }
 
 func processAuditEvent(ctx context.Context, sink audit.Sink, ev *auditinternal.Event, omitStages []auditinternal.Stage) bool {

pkg/endpoints/filters/authorization.go

@@ -49,7 +49,6 @@ func WithAuthorization(handler http.Handler, a authorizer.Authorizer, s runtime.
 	}
 	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 		ctx := req.Context()
-		ae := audit.AuditEventFrom(ctx)
 
 		attributes, err := GetAuthorizerAttributes(ctx)
 		if err != nil {
@@ -59,20 +58,22 @@ func WithAuthorization(handler http.Handler, a authorizer.Authorizer, s runtime.
 		authorized, reason, err := a.Authorize(ctx, attributes)
 		// an authorizer like RBAC could encounter evaluation errors and still allow the request, so authorizer decision is checked before error here.
 		if authorized == authorizer.DecisionAllow {
-			audit.LogAnnotation(ae, decisionAnnotationKey, decisionAllow)
-			audit.LogAnnotation(ae, reasonAnnotationKey, reason)
+			audit.AddAuditAnnotations(ctx,
+				decisionAnnotationKey, decisionAllow,
+				reasonAnnotationKey, reason)
 			handler.ServeHTTP(w, req)
 			return
 		}
 		if err != nil {
-			audit.LogAnnotation(ae, reasonAnnotationKey, reasonError)
+			audit.AddAuditAnnotation(ctx, reasonAnnotationKey, reasonError)
 			responsewriters.InternalError(w, req, err)
 			return
 		}
 
 		klog.V(4).InfoS("Forbidden", "URI", req.RequestURI, "Reason", reason)
-		audit.LogAnnotation(ae, decisionAnnotationKey, decisionForbid)
-		audit.LogAnnotation(ae, reasonAnnotationKey, reason)
+		audit.AddAuditAnnotations(ctx,
+			decisionAnnotationKey, decisionForbid,
+			reasonAnnotationKey, reason)
 		responsewriters.Forbidden(ctx, attributes, w, req, reason, s)
 	})
 }

pkg/endpoints/handlers/create.go

@@ -157,8 +157,7 @@ func createHandler(r rest.NamedCreater, scope *RequestScope, admit admission.Int
 		}
 		ctx = request.WithNamespace(ctx, namespace)
 
-		ae := audit.AuditEventFrom(ctx)
-		admit = admission.WithAudit(admit, ae)
+		admit = admission.WithAudit(admit)
 		audit.LogRequestObject(req.Context(), obj, objGV, scope.Resource, scope.Subresource, scope.Serializer)
 
 		userInfo, _ := request.UserFrom(ctx)