Add trace to webhook invocations

staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/conversion/BUILD

@@ -29,6 +29,7 @@ go_library(
         "//staging/src/k8s.io/client-go/kubernetes/scheme:go_default_library",
         "//staging/src/k8s.io/client-go/rest:go_default_library",
         "//vendor/github.com/prometheus/client_golang/prometheus:go_default_library",
+        "//vendor/k8s.io/utils/trace:go_default_library",
     ],
 )
 

staging/src/k8s.io/apiextensions-apiserver/pkg/apiserver/conversion/webhook_converter.go

@@ -19,6 +19,7 @@ package conversion
 import (
 	"context"
 	"fmt"
+	"time"
 
 	apivalidation "k8s.io/apimachinery/pkg/api/validation"
 	v1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -33,6 +34,7 @@ import (
 
 	internal "k8s.io/apiextensions-apiserver/pkg/apis/apiextensions"
 	"k8s.io/apiextensions-apiserver/pkg/apis/apiextensions/v1beta1"
+	utiltrace "k8s.io/utils/trace"
 )
 
 type webhookConverterFactory struct {
@@ -170,7 +172,8 @@ func (c *webhookConverter) Convert(in runtime.Object, toGV schema.GroupVersion)
 	}
 
 	request := createConversionReview(in, toGV.String())
-	if len(request.Request.Objects) == 0 {
+	objCount := len(request.Request.Objects)
+	if objCount == 0 {
 		if !isList {
 			return in, nil
 		}
@@ -178,6 +181,15 @@ func (c *webhookConverter) Convert(in runtime.Object, toGV schema.GroupVersion)
 		out.SetAPIVersion(toGV.String())
 		return out, nil
 	}
+
+	trace := utiltrace.New(fmt.Sprintf(
+		"Call conversion webhook: custom resource definition: %s, desired API version: %s, object count: %d, UID: %v",
+		c.name, request.Request.DesiredAPIVersion, objCount, request.Request.UID))
+	// Only log conversion webhook traces that exceed a 8ms per object limit plus a 50ms request overhead allowance.
+	// The per object limit uses the SLO for conversion webhooks (~4ms per object) plus time to serialize/deserialize
+	// the conversion request on the apiserver side (~4ms per object).
+	defer trace.LogIfLong(time.Duration(50+8*objCount) * time.Millisecond)
+
 	response := &v1beta1.ConversionReview{}
 	// TODO: Figure out if adding one second timeout make sense here.
 	ctx := context.TODO()
@@ -186,6 +198,7 @@ func (c *webhookConverter) Convert(in runtime.Object, toGV schema.GroupVersion)
 		// TODO: Return a webhook specific error to be able to convert it to meta.Status
 		return nil, fmt.Errorf("conversion webhook for %v failed: %v", in.GetObjectKind(), err)
 	}
+	trace.Step("Request completed")
 
 	if response.Response == nil {
 		// TODO: Return a webhook specific error to be able to convert it to meta.Status

staging/src/k8s.io/apiserver/pkg/admission/configuration/mutating_webhook_manager.go

@@ -93,7 +93,7 @@ func mergeMutatingWebhookConfigurations(configurations []*v1beta1.MutatingWebhoo
 			n := c.Webhooks[i].Name
 			uid := fmt.Sprintf("%s/%s/%d", c.Name, n, names[n])
 			names[n]++
-			accessors = append(accessors, webhook.NewMutatingWebhookAccessor(uid, &c.Webhooks[i]))
+			accessors = append(accessors, webhook.NewMutatingWebhookAccessor(uid, c.Name, &c.Webhooks[i]))
 		}
 	}
 	return accessors

staging/src/k8s.io/apiserver/pkg/admission/configuration/validating_webhook_manager.go

@@ -91,7 +91,7 @@ func mergeValidatingWebhookConfigurations(configurations []*v1beta1.ValidatingWe
 			n := c.Webhooks[i].Name
 			uid := fmt.Sprintf("%s/%s/%d", c.Name, n, names[n])
 			names[n]++
-			accessors = append(accessors, webhook.NewValidatingWebhookAccessor(uid, &c.Webhooks[i]))
+			accessors = append(accessors, webhook.NewValidatingWebhookAccessor(uid, c.Name, &c.Webhooks[i]))
 		}
 	}
 	return accessors

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/accessors.go

@@ -26,6 +26,9 @@ type WebhookAccessor interface {
 	// GetUID gets a string that uniquely identifies the webhook.
 	GetUID() string
 
+	// GetConfigurationName gets the name of the webhook configuration that owns this webhook.
+	GetConfigurationName() string
+
 	// GetName gets the webhook Name field. Note that the name is scoped to the webhook
 	// configuration and does not provide a globally unique identity, if a unique identity is
 	// needed, use GetUID.
@@ -56,45 +59,60 @@ type WebhookAccessor interface {
 }
 
 // NewMutatingWebhookAccessor creates an accessor for a MutatingWebhook.
-func NewMutatingWebhookAccessor(uid string, h *v1beta1.MutatingWebhook) WebhookAccessor {
+func NewMutatingWebhookAccessor(uid, configurationName string, h *v1beta1.MutatingWebhook) WebhookAccessor {
-	return mutatingWebhookAccessor{uid: uid, MutatingWebhook: h}
+	return mutatingWebhookAccessor{uid: uid, configurationName: configurationName, MutatingWebhook: h}
 }
 
 type mutatingWebhookAccessor struct {
 	*v1beta1.MutatingWebhook
 	uid               string
+	configurationName string
 }
 
 func (m mutatingWebhookAccessor) GetUID() string {
 	return m.uid
 }
+
+func (m mutatingWebhookAccessor) GetConfigurationName() string {
+	return m.configurationName
+}
+
 func (m mutatingWebhookAccessor) GetName() string {
 	return m.Name
 }
+
 func (m mutatingWebhookAccessor) GetClientConfig() v1beta1.WebhookClientConfig {
 	return m.ClientConfig
 }
+
 func (m mutatingWebhookAccessor) GetRules() []v1beta1.RuleWithOperations {
 	return m.Rules
 }
+
 func (m mutatingWebhookAccessor) GetFailurePolicy() *v1beta1.FailurePolicyType {
 	return m.FailurePolicy
 }
+
 func (m mutatingWebhookAccessor) GetMatchPolicy() *v1beta1.MatchPolicyType {
 	return m.MatchPolicy
 }
+
 func (m mutatingWebhookAccessor) GetNamespaceSelector() *metav1.LabelSelector {
 	return m.NamespaceSelector
 }
+
 func (m mutatingWebhookAccessor) GetObjectSelector() *metav1.LabelSelector {
 	return m.ObjectSelector
 }
+
 func (m mutatingWebhookAccessor) GetSideEffects() *v1beta1.SideEffectClass {
 	return m.SideEffects
 }
+
 func (m mutatingWebhookAccessor) GetTimeoutSeconds() *int32 {
 	return m.TimeoutSeconds
 }
+
 func (m mutatingWebhookAccessor) GetAdmissionReviewVersions() []string {
 	return m.AdmissionReviewVersions
 }
@@ -108,45 +126,60 @@ func (m mutatingWebhookAccessor) GetValidatingWebhook() (*v1beta1.ValidatingWebh
 }
 
 // NewValidatingWebhookAccessor creates an accessor for a ValidatingWebhook.
-func NewValidatingWebhookAccessor(uid string, h *v1beta1.ValidatingWebhook) WebhookAccessor {
+func NewValidatingWebhookAccessor(uid, configurationName string, h *v1beta1.ValidatingWebhook) WebhookAccessor {
-	return validatingWebhookAccessor{uid: uid, ValidatingWebhook: h}
+	return validatingWebhookAccessor{uid: uid, configurationName: configurationName, ValidatingWebhook: h}
 }
 
 type validatingWebhookAccessor struct {
 	*v1beta1.ValidatingWebhook
 	uid               string
+	configurationName string
 }
 
 func (v validatingWebhookAccessor) GetUID() string {
 	return v.uid
 }
+
+func (v validatingWebhookAccessor) GetConfigurationName() string {
+	return v.configurationName
+}
+
 func (v validatingWebhookAccessor) GetName() string {
 	return v.Name
 }
+
 func (v validatingWebhookAccessor) GetClientConfig() v1beta1.WebhookClientConfig {
 	return v.ClientConfig
 }
+
 func (v validatingWebhookAccessor) GetRules() []v1beta1.RuleWithOperations {
 	return v.Rules
 }
+
 func (v validatingWebhookAccessor) GetFailurePolicy() *v1beta1.FailurePolicyType {
 	return v.FailurePolicy
 }
+
 func (v validatingWebhookAccessor) GetMatchPolicy() *v1beta1.MatchPolicyType {
 	return v.MatchPolicy
 }
+
 func (v validatingWebhookAccessor) GetNamespaceSelector() *metav1.LabelSelector {
 	return v.NamespaceSelector
 }
+
 func (v validatingWebhookAccessor) GetObjectSelector() *metav1.LabelSelector {
 	return v.ObjectSelector
 }
+
 func (v validatingWebhookAccessor) GetSideEffects() *v1beta1.SideEffectClass {
 	return v.SideEffects
 }
+
 func (v validatingWebhookAccessor) GetTimeoutSeconds() *int32 {
 	return v.TimeoutSeconds
 }
+
 func (v validatingWebhookAccessor) GetAdmissionReviewVersions() []string {
 	return v.AdmissionReviewVersions
 }

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/accessors_test.go

@@ -37,7 +37,7 @@ func TestMutatingWebhookAccessor(t *testing.T) {
 			orig.ReinvocationPolicy = nil
 
 			uid := fmt.Sprintf("test.configuration.admission/%s/0", orig.Name)
-			accessor := NewMutatingWebhookAccessor(uid, orig)
+			accessor := NewMutatingWebhookAccessor(uid, "test.configuration.admission", orig)
 			if uid != accessor.GetUID() {
 				t.Errorf("expected GetUID to return %s, but got %s", accessor.GetUID(), uid)
 			}
@@ -77,7 +77,7 @@ func TestValidatingWebhookAccessor(t *testing.T) {
 			orig := &v1beta1.ValidatingWebhook{}
 			f.Fuzz(orig)
 			uid := fmt.Sprintf("test.configuration.admission/%s/0", orig.Name)
-			accessor := NewValidatingWebhookAccessor(uid, orig)
+			accessor := NewValidatingWebhookAccessor(uid, "test.configuration.admission", orig)
 			if uid != accessor.GetUID() {
 				t.Errorf("expected GetUID to return %s, but got %s", accessor.GetUID(), uid)
 			}

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/generic/webhook_test.go

@@ -293,7 +293,7 @@ func TestShouldCallHook(t *testing.T) {
 
 	for i, testcase := range testcases {
 		t.Run(testcase.name, func(t *testing.T) {
-			invocation, err := a.ShouldCallHook(webhook.NewValidatingWebhookAccessor(fmt.Sprintf("webhook-%d", i), testcase.webhook), testcase.attrs, interfaces)
+			invocation, err := a.ShouldCallHook(webhook.NewValidatingWebhookAccessor(fmt.Sprintf("webhook-%d", i), fmt.Sprintf("webhook-cfg-%d", i), testcase.webhook), testcase.attrs, interfaces)
 			if err != nil {
 				if len(testcase.expectErr) == 0 {
 					t.Fatal(err)

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/mutating/BUILD

@@ -32,6 +32,7 @@ go_library(
         "//staging/src/k8s.io/apiserver/pkg/util/webhook:go_default_library",
         "//vendor/github.com/evanphx/json-patch:go_default_library",
         "//vendor/k8s.io/klog:go_default_library",
+        "//vendor/k8s.io/utils/trace:go_default_library",
     ],
 )
 

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/mutating/dispatcher.go

@@ -42,6 +42,7 @@ import (
 	webhookrequest "k8s.io/apiserver/pkg/admission/plugin/webhook/request"
 	"k8s.io/apiserver/pkg/admission/plugin/webhook/util"
 	webhookutil "k8s.io/apiserver/pkg/util/webhook"
+	utiltrace "k8s.io/utils/trace"
 )
 
 type mutatingDispatcher struct {
@@ -172,6 +173,10 @@ func (a *mutatingDispatcher) callAttrMutatingHook(ctx context.Context, h *v1beta
 	if err != nil {
 		return false, &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
 	}
+	trace := utiltrace.New(fmt.Sprintf("Call mutating webhook: configuration: %s, webhook: %s, resource: %v, subResource: %s, operation: %v, UID: %v",
+		invocation.Webhook.GetConfigurationName(), h.Name, request.Request.Resource, request.Request.SubResource, request.Request.Operation, request.Request.UID))
+	defer trace.LogIfLong(500 * time.Millisecond)
+	response := &admissionv1beta1.AdmissionReview{}
 	r := client.Post().Context(ctx).Body(request)
 	if h.TimeoutSeconds != nil {
 		r = r.Timeout(time.Duration(*h.TimeoutSeconds) * time.Second)
@@ -179,6 +184,7 @@ func (a *mutatingDispatcher) callAttrMutatingHook(ctx context.Context, h *v1beta
 	if err := r.Do().Into(response); err != nil {
 		return false, &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
 	}
+	trace.Step("Request completed")
 
 	result, err := webhookrequest.VerifyAdmissionResponse(uid, true, response)
 	if err != nil {
@@ -248,7 +254,7 @@ func (a *mutatingDispatcher) callAttrMutatingHook(ctx context.Context, h *v1beta
 	}
 
 	changed := !apiequality.Semantic.DeepEqual(attr.VersionedObject, newVersionedObject)
-
+	trace.Step("Patch applied")
 	attr.Dirty = true
 	attr.VersionedObject = newVersionedObject
 	o.GetObjectDefaulter().Default(attr.VersionedObject)

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/namespace/matcher_test.go

@@ -120,7 +120,7 @@ func TestNotExemptClusterScopedResource(t *testing.T) {
 	}
 	attr := admission.NewAttributesRecord(nil, nil, schema.GroupVersionKind{}, "", "mock-name", schema.GroupVersionResource{Version: "v1", Resource: "nodes"}, "", admission.Create, &metav1.CreateOptions{}, false, nil)
 	matcher := Matcher{}
-	matches, err := matcher.MatchNamespaceSelector(webhook.NewValidatingWebhookAccessor("mock-hook", hook), attr)
+	matches, err := matcher.MatchNamespaceSelector(webhook.NewValidatingWebhookAccessor("mock-hook", "mock-cfg", hook), attr)
 	if err != nil {
 		t.Fatal(err)
 	}

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/object/matcher_test.go

@@ -115,7 +115,7 @@ func TestObjectSelector(t *testing.T) {
 			}}}
 
 		t.Run(testcase.name, func(t *testing.T) {
-			match, err := matcher.MatchObjectSelector(webhook.NewValidatingWebhookAccessor("mock-hook", hook), testcase.attrs)
+			match, err := matcher.MatchObjectSelector(webhook.NewValidatingWebhookAccessor("mock-hook", "mock-cfg", hook), testcase.attrs)
 			if err != nil {
 				t.Error(err)
 			}

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/request/admissionreview_test.go

@@ -486,14 +486,14 @@ func TestCreateAdmissionObjects(t *testing.T) {
 		{
 			name: "no supported versions",
 			invocation: &generic.WebhookInvocation{
-				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", &admissionregistrationv1beta1.MutatingWebhook{}),
+				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", "mycfg", &admissionregistrationv1beta1.MutatingWebhook{}),
 			},
 			expectErr: "webhook does not accept known AdmissionReview versions",
 		},
 		{
 			name: "no known supported versions",
 			invocation: &generic.WebhookInvocation{
-				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", &admissionregistrationv1beta1.MutatingWebhook{
+				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", "mycfg", &admissionregistrationv1beta1.MutatingWebhook{
 					AdmissionReviewVersions: []string{"vX"},
 				}),
 			},
@@ -510,7 +510,7 @@ func TestCreateAdmissionObjects(t *testing.T) {
 				Resource:    schema.GroupVersionResource{Group: "extensions", Version: "v1beta1", Resource: "deployments"},
 				Subresource: "",
 				Kind:        schema.GroupVersionKind{Group: "extensions", Version: "v1beta1", Kind: "Deployment"},
-				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", &admissionregistrationv1beta1.MutatingWebhook{
+				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", "mycfg", &admissionregistrationv1beta1.MutatingWebhook{
 					AdmissionReviewVersions: []string{"v1", "v1beta1"},
 				}),
 			},
@@ -553,7 +553,7 @@ func TestCreateAdmissionObjects(t *testing.T) {
 				Resource:    schema.GroupVersionResource{Group: "extensions", Version: "v1beta1", Resource: "deployments"},
 				Subresource: "",
 				Kind:        schema.GroupVersionKind{Group: "extensions", Version: "v1beta1", Kind: "Deployment"},
-				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", &admissionregistrationv1beta1.MutatingWebhook{
+				Webhook: webhook.NewMutatingWebhookAccessor("mywebhook", "mycfg", &admissionregistrationv1beta1.MutatingWebhook{
 					AdmissionReviewVersions: []string{"v1beta1", "v1"},
 				}),
 			},

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/validating/BUILD

@@ -25,6 +25,7 @@ go_library(
         "//staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/util:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/util/webhook:go_default_library",
         "//vendor/k8s.io/klog:go_default_library",
+        "//vendor/k8s.io/utils/trace:go_default_library",
     ],
 )
 

staging/src/k8s.io/apiserver/pkg/admission/plugin/webhook/validating/dispatcher.go

@@ -35,6 +35,7 @@ import (
 	"k8s.io/apiserver/pkg/admission/plugin/webhook/util"
 	webhookutil "k8s.io/apiserver/pkg/util/webhook"
 	"k8s.io/klog"
+	utiltrace "k8s.io/utils/trace"
 )
 
 type validatingDispatcher struct {
@@ -153,6 +154,10 @@ func (d *validatingDispatcher) callHook(ctx context.Context, h *v1beta1.Validati
 	if err != nil {
 		return &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
 	}
+	trace := utiltrace.New(fmt.Sprintf("Call validating webhook: configuration: %s, webhook: %s, resource: %v, subResource: %s, operation: %v, UID: %v",
+		invocation.Webhook.GetConfigurationName(), h.Name, request.Request.Resource, request.Request.SubResource, request.Request.Operation, request.Request.UID))
+	defer trace.LogIfLong(500 * time.Millisecond)
+	response := &admissionv1beta1.AdmissionReview{}
 	r := client.Post().Context(ctx).Body(request)
 	if h.TimeoutSeconds != nil {
 		r = r.Timeout(time.Duration(*h.TimeoutSeconds) * time.Second)
@@ -160,6 +165,7 @@ func (d *validatingDispatcher) callHook(ctx context.Context, h *v1beta1.Validati
 	if err := r.Do().Into(response); err != nil {
 		return &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
 	}
+	trace.Step("Request completed")
 
 	result, err := webhookrequest.VerifyAdmissionResponse(uid, false, response)
 	if err != nil {

staging/src/k8s.io/apiserver/plugin/pkg/audit/webhook/BUILD

@@ -36,6 +36,7 @@ go_library(
         "//staging/src/k8s.io/apiserver/pkg/audit:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/util/webhook:go_default_library",
         "//staging/src/k8s.io/client-go/rest:go_default_library",
+        "//vendor/k8s.io/utils/trace:go_default_library",
     ],
 )
 

staging/src/k8s.io/apiserver/plugin/pkg/audit/webhook/webhook.go

@@ -27,6 +27,7 @@ import (
 	"k8s.io/apiserver/pkg/audit"
 	"k8s.io/apiserver/pkg/util/webhook"
 	"k8s.io/client-go/rest"
+	utiltrace "k8s.io/utils/trace"
 )
 
 const (
@@ -95,6 +96,12 @@ func (b *backend) processEvents(ev ...*auditinternal.Event) error {
 		list.Items = append(list.Items, *e)
 	}
 	return b.w.WithExponentialBackoff(func() rest.Result {
+		trace := utiltrace.New(fmt.Sprintf("Audit events webhook request for %s, event list count: %d", b.name, len(list.Items)))
+		// Only log audit webhook traces that exceed a 25ms per object limit plus a 50ms
+		// request overhead allowance. The high per object limit used here is primarily to
+		// allow enough time for the serialization/deserialization of audit events, which
+		// contain nested request and response objects plus additional event fields.
+		defer trace.LogIfLong(time.Duration(50+25*len(list.Items)) * time.Millisecond)
 		return b.w.RestClient.Post().Body(&list).Do()
 	}).Error()
 }

staging/src/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go

@@ -18,12 +18,11 @@ package apiserver
 
 import (
 	"context"
+	"k8s.io/klog"
 	"net/http"
 	"net/url"
 	"sync/atomic"
 
-	"k8s.io/klog"
-
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/util/httpstream"
 	"k8s.io/apimachinery/pkg/util/httpstream/spdy"