Merge pull request #130571 from hakuna-matatah/debug-upstream

Help debug latencies in authn and authz phase of Request

Kubernetes-commit: 2b025e645975d6d51bf38c008f972c632cf49657

go.mod

@@ -50,7 +50,7 @@ require (
 	gopkg.in/go-jose/go-jose.v2 v2.6.3
 	gopkg.in/natefinch/lumberjack.v2 v2.2.1
 	k8s.io/api v0.0.0-20250302000304-d98e88306c64
-	k8s.io/apimachinery v0.0.0-20250304225002-e93b7f2f82c3
+	k8s.io/apimachinery v0.0.0-20250305172805-b5eba295a2b2
 	k8s.io/client-go v0.0.0-20250302000636-ec8a292223d9
 	k8s.io/component-base v0.0.0-20250305013914-e05800f2e236
 	k8s.io/klog/v2 v2.130.1

go.sum

@@ -367,8 +367,8 @@ honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWh
 honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 k8s.io/api v0.0.0-20250302000304-d98e88306c64 h1:usPcU79ne5EPNj5qlw51vCMZrDLsNhute8ORJB5HkGA=
 k8s.io/api v0.0.0-20250302000304-d98e88306c64/go.mod h1:TbBpVuQjoXdOhqO78T/K+NHq7MV5uCp3fUKjTS5yvCs=
-k8s.io/apimachinery v0.0.0-20250304225002-e93b7f2f82c3 h1:d1LeSkraNfCGQksg7TPaPU62mC4LlJsSWmviCQ0BGG0=
-k8s.io/apimachinery v0.0.0-20250304225002-e93b7f2f82c3/go.mod h1:0rVRgdlgja0MQ+SYCognm5pRNteQOvhHAsDpKOs48GU=
+k8s.io/apimachinery v0.0.0-20250305172805-b5eba295a2b2 h1:iAVfZx3J+4gJEA7PCUM9rzwSa8WEAtMri4hLAkNHZQU=
+k8s.io/apimachinery v0.0.0-20250305172805-b5eba295a2b2/go.mod h1:0rVRgdlgja0MQ+SYCognm5pRNteQOvhHAsDpKOs48GU=
 k8s.io/client-go v0.0.0-20250302000636-ec8a292223d9 h1:RsjtLwH878+j/TXxa4Llu1gUu6T2eeWgePO3GKTicj8=
 k8s.io/client-go v0.0.0-20250302000636-ec8a292223d9/go.mod h1:pXNpqxTwJbeA0hnbKUjpV7EISwuPYW0HnykV3Mkltqw=
 k8s.io/component-base v0.0.0-20250305013914-e05800f2e236 h1:0/tKvYfoNXKLOVhzo7XNtwBKtQ1Qv37YIc9DYajC//U=

pkg/endpoints/filters/authentication.go

@@ -68,6 +68,7 @@ func withAuthentication(handler http.Handler, auth authenticator.Request, failed
 		authenticationFinish := time.Now()
 		defer func() {
 			metrics(req.Context(), resp, ok, err, apiAuds, authenticationStart, authenticationFinish)
+			genericapirequest.TrackAuthenticationLatency(req.Context(), authenticationFinish.Sub(authenticationStart))
 		}()
 		if err != nil || !ok {
 			if err != nil {
@@ -118,7 +119,6 @@ func withAuthentication(handler http.Handler, auth authenticator.Request, failed
 			// https://github.com/golang/net/commit/97aa3a539ec716117a9d15a4659a911f50d13c3c
 			w.Header().Set("Connection", "close")
 		}
-
 		req = req.WithContext(genericapirequest.WithUser(req.Context(), resp.User))
 		handler.ServeHTTP(w, req)
 	})

pkg/endpoints/filters/authorization.go

@@ -73,6 +73,7 @@ func withAuthorization(handler http.Handler, a authorizer.Authorizer, s runtime.
 		authorizationFinish := time.Now()
 		defer func() {
 			metrics(ctx, authorized, err, authorizationStart, authorizationFinish)
+			request.TrackAuthorizationLatency(ctx, authorizationFinish.Sub(authorizationStart))
 		}()
 
 		// an authorizer like RBAC could encounter evaluation errors and still allow the request, so authorizer decision is checked before error here.

pkg/endpoints/request/webhook_duration.go

@@ -116,6 +116,12 @@ type LatencyTrackers struct {
 	// Validate webhooks are done in parallel, so max function is used.
 	ValidatingWebhookTracker DurationTracker
 
+	// AuthenticationTracker tracks the latency incurred by Authentication of request
+	AuthenticationTracker DurationTracker
+
+	// AuthorizationTracker tracks the latency incurred by Authorization of request
+	AuthorizationTracker DurationTracker
+
 	// APFQueueWaitTracker tracks the latency incurred by queue wait times
 	// from priority & fairness.
 	APFQueueWaitTracker DurationTracker
@@ -179,6 +185,8 @@ func WithLatencyTrackersAndCustomClock(parent context.Context, c clock.Clock) co
 	return WithValue(parent, latencyTrackersKey, &LatencyTrackers{
 		MutatingWebhookTracker:   newSumLatencyTracker(c),
 		ValidatingWebhookTracker: newMaxLatencyTracker(c),
+		AuthenticationTracker:    newSumLatencyTracker(c),
+		AuthorizationTracker:     newMaxLatencyTracker(c),
 		APFQueueWaitTracker:      newMaxLatencyTracker(c),
 		StorageTracker:           newSumLatencyTracker(c),
 		TransformTracker:         newSumLatencyTracker(c),
@@ -243,6 +251,22 @@ func TrackResponseWriteLatency(ctx context.Context, d time.Duration) {
 	}
 }
 
+// TrackAuthenticationLatency is used to track latency incurred
+// by Authentication phase of request.
+func TrackAuthenticationLatency(ctx context.Context, d time.Duration) {
+	if tracker, ok := LatencyTrackersFrom(ctx); ok {
+		tracker.AuthenticationTracker.TrackDuration(d)
+	}
+}
+
+// TrackAuthorizationLatency is used to track latency incurred
+// by Authorization phase of request.
+func TrackAuthorizationLatency(ctx context.Context, d time.Duration) {
+	if tracker, ok := LatencyTrackersFrom(ctx); ok {
+		tracker.AuthorizationTracker.TrackDuration(d)
+	}
+}
+
 // TrackAPFQueueWaitLatency is used to track latency incurred
 // by priority and fairness queues.
 func TrackAPFQueueWaitLatency(ctx context.Context, d time.Duration) {
@@ -275,6 +299,8 @@ func AuditAnnotationsFromLatencyTrackers(ctx context.Context) map[string]string
 		validatingWebhookLatencyKey = "apiserver.latency.k8s.io/validating-webhook"
 		decodeLatencyKey            = "apiserver.latency.k8s.io/decode-response-object"
 		apfQueueWaitLatencyKey      = "apiserver.latency.k8s.io/apf-queue-wait"
+		authenticationLatencyKey    = "apiserver.latency.k8s.io/authentication"
+		authorizationLatencyKey     = "apiserver.latency.k8s.io/authorization"
 	)
 
 	tracker, ok := LatencyTrackersFrom(ctx)
@@ -307,5 +333,11 @@ func AuditAnnotationsFromLatencyTrackers(ctx context.Context) map[string]string
 	if latency := tracker.APFQueueWaitTracker.GetLatency(); latency != 0 {
 		annotations[apfQueueWaitLatencyKey] = latency.String()
 	}
+	if latency := tracker.AuthenticationTracker.GetLatency(); latency != 0 {
+		annotations[authenticationLatencyKey] = latency.String()
+	}
+	if latency := tracker.AuthorizationTracker.GetLatency(); latency != 0 {
+		annotations[authorizationLatencyKey] = latency.String()
+	}
 	return annotations
 }