Add `apiserver_authentication_jwt_authenticator_latency_seconds` metric

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

Kubernetes-commit: 0da5e8137b839860d55938ceb6d520caba3fc776

plugin/pkg/authenticator/token/oidc/metrics.go

@@ -0,0 +1,106 @@
+/*
+Copyright 2024 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package oidc
+
+import (
+	"context"
+	"crypto/sha256"
+	"fmt"
+	"k8s.io/utils/clock"
+	"sync"
+	"time"
+
+	"k8s.io/apiserver/pkg/authentication/authenticator"
+	"k8s.io/component-base/metrics"
+	"k8s.io/component-base/metrics/legacyregistry"
+)
+
+const (
+	namespace = "apiserver"
+	subsystem = "authentication"
+)
+
+var (
+	jwtAuthenticatorLatencyMetric = metrics.NewHistogramVec(
+		&metrics.HistogramOpts{
+			Namespace:      namespace,
+			Subsystem:      subsystem,
+			Name:           "jwt_authenticator_latency_seconds",
+			Help:           "Latency of jwt authentication operations in seconds. This is the time spent authenticating a token for cache miss only (i.e. when the token is not found in the cache).",
+			StabilityLevel: metrics.ALPHA,
+			// default histogram buckets with a 1ms starting point
+			Buckets: []float64{.001, .005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10},
+		},
+		[]string{"result", "jwt_issuer_hash"},
+	)
+)
+
+var registerMetrics sync.Once
+
+func RegisterMetrics() {
+	registerMetrics.Do(func() {
+		legacyregistry.MustRegister(jwtAuthenticatorLatencyMetric)
+	})
+}
+
+func recordAuthenticationLatency(result, jwtIssuerHash string, duration time.Duration) {
+	jwtAuthenticatorLatencyMetric.WithLabelValues(result, jwtIssuerHash).Observe(duration.Seconds())
+}
+
+func getHash(data string) string {
+	if len(data) > 0 {
+		return fmt.Sprintf("sha256:%x", sha256.Sum256([]byte(data)))
+	}
+	return ""
+}
+
+func newInstrumentedAuthenticator(jwtIssuer string, delegate authenticator.Token) authenticator.Token {
+	return newInstrumentedAuthenticatorWithClock(jwtIssuer, delegate, clock.RealClock{})
+}
+
+func newInstrumentedAuthenticatorWithClock(jwtIssuer string, delegate authenticator.Token, clock clock.PassiveClock) *instrumentedAuthenticator {
+	RegisterMetrics()
+	return &instrumentedAuthenticator{
+		jwtIssuerHash: getHash(jwtIssuer),
+		delegate:      delegate,
+		clock:         clock,
+	}
+}
+
+type instrumentedAuthenticator struct {
+	jwtIssuerHash string
+	delegate      authenticator.Token
+	clock         clock.PassiveClock
+}
+
+func (a *instrumentedAuthenticator) AuthenticateToken(ctx context.Context, token string) (*authenticator.Response, bool, error) {
+	start := a.clock.Now()
+	response, ok, err := a.delegate.AuthenticateToken(ctx, token)
+	// this only happens when issuer doesn't match the authenticator
+	// we don't want to record metrics for this case
+	if !ok && err == nil {
+		return response, ok, err
+	}
+
+	duration := a.clock.Since(start)
+	if err != nil {
+		recordAuthenticationLatency("failure", a.jwtIssuerHash, duration)
+	} else {
+		recordAuthenticationLatency("success", a.jwtIssuerHash, duration)
+	}
+	return response, ok, err
+}

plugin/pkg/authenticator/token/oidc/metrics_test.go

@@ -0,0 +1,129 @@
+/*
+Copyright 2024 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package oidc
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"testing"
+	"time"
+
+	"k8s.io/apiserver/pkg/authentication/authenticator"
+	"k8s.io/component-base/metrics/legacyregistry"
+	"k8s.io/component-base/metrics/testutil"
+)
+
+const (
+	testIssuer = "testIssuer"
+)
+
+func TestRecordAuthenticationLatency(t *testing.T) {
+	tests := []struct {
+		name            string
+		authenticator   authenticator.Token
+		generateMetrics func()
+		expectedValue   string
+	}{
+		{
+			name:          "success",
+			authenticator: &dummyAuthenticator{response: &authenticator.Response{}, ok: true},
+			expectedValue: `
+        # HELP apiserver_authentication_jwt_authenticator_latency_seconds [ALPHA] Latency of jwt authentication operations in seconds. This is the time spent authenticating a token for cache miss only (i.e. when the token is not found in the cache).
+        # TYPE apiserver_authentication_jwt_authenticator_latency_seconds histogram
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.001"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.005"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.01"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.025"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.05"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.1"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.25"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="0.5"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="1"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="2.5"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="5"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="10"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success",le="+Inf"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_sum{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success"} 1e-09
+        apiserver_authentication_jwt_authenticator_latency_seconds_count{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="success"} 1
+		`,
+		},
+		{
+			name:          "error",
+			authenticator: &dummyAuthenticator{response: &authenticator.Response{}, ok: false, err: fmt.Errorf("error")},
+			expectedValue: `
+        # HELP apiserver_authentication_jwt_authenticator_latency_seconds [ALPHA] Latency of jwt authentication operations in seconds. This is the time spent authenticating a token for cache miss only (i.e. when the token is not found in the cache).
+        # TYPE apiserver_authentication_jwt_authenticator_latency_seconds histogram
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.001"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.005"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.01"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.025"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.05"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.1"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.25"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="0.5"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="1"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="2.5"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="5"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="10"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_bucket{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure",le="+Inf"} 1
+        apiserver_authentication_jwt_authenticator_latency_seconds_sum{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure"} 1e-09
+        apiserver_authentication_jwt_authenticator_latency_seconds_count{jwt_issuer_hash="sha256:29b34beedc55b972f2428f21bc588f9d38e5e8f7a7af825486e7bb4fd9caa2ad",result="failure"} 1
+		`,
+		},
+		{
+			name:          "no metrics when issuer doesn't match",
+			authenticator: &dummyAuthenticator{response: &authenticator.Response{}, ok: false, err: nil},
+			expectedValue: "",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			jwtAuthenticatorLatencyMetric.Reset()
+			RegisterMetrics()
+
+			a := newInstrumentedAuthenticatorWithClock(testIssuer, tt.authenticator, dummyClock{})
+			_, _, _ = a.AuthenticateToken(context.Background(), "token")
+
+			if err := testutil.GatherAndCompare(legacyregistry.DefaultGatherer, strings.NewReader(tt.expectedValue), "apiserver_authentication_jwt_authenticator_latency_seconds"); err != nil {
+				t.Fatal(err)
+			}
+		})
+	}
+}
+
+type dummyAuthenticator struct {
+	response *authenticator.Response
+	ok       bool
+	err      error
+}
+
+func (a *dummyAuthenticator) AuthenticateToken(ctx context.Context, token string) (*authenticator.Response, bool, error) {
+	return a.response, a.ok, a.err
+}
+
+type dummyClock struct {
+}
+
+func (d dummyClock) Now() time.Time {
+	return time.Now()
+}
+
+func (d dummyClock) Since(t time.Time) time.Duration {
+	return time.Duration(1)
+}

plugin/pkg/authenticator/token/oidc/oidc.go

@@ -221,7 +221,7 @@ var allowedSigningAlgs = map[string]bool{
 	oidc.PS512: true,
 }
 
-func New(opts Options) (*Authenticator, error) {
+func New(opts Options) (authenticator.Token, error) {
 	celMapper, fieldErr := apiservervalidation.CompileAndValidateJWTAuthenticator(opts.JWTAuthenticator)
 	if err := fieldErr.ToAggregate(); err != nil {
 		return nil, err
@@ -313,17 +313,18 @@ func New(opts Options) (*Authenticator, error) {
 		requiredClaims:   requiredClaims,
 	}
 
+	issuerURL := opts.JWTAuthenticator.Issuer.URL
 	if opts.KeySet != nil {
 		// We already have a key set, synchronously initialize the verifier.
 		authenticator.setVerifier(&idTokenVerifier{
-			oidc.NewVerifier(opts.JWTAuthenticator.Issuer.URL, opts.KeySet, verifierConfig),
+			oidc.NewVerifier(issuerURL, opts.KeySet, verifierConfig),
 			audiences,
 		})
 	} else {
 		// Asynchronously attempt to initialize the authenticator. This enables
 		// self-hosted providers, providers that run on top of Kubernetes itself.
 		go wait.PollImmediateUntil(10*time.Second, func() (done bool, err error) {
-			provider, err := oidc.NewProvider(ctx, opts.JWTAuthenticator.Issuer.URL)
+			provider, err := oidc.NewProvider(ctx, issuerURL)
 			if err != nil {
 				klog.Errorf("oidc authenticator: initializing plugin: %v", err)
 				return false, nil
@@ -335,7 +336,7 @@ func New(opts Options) (*Authenticator, error) {
 		}, ctx.Done())
 	}
 
-	return authenticator, nil
+	return newInstrumentedAuthenticator(issuerURL, authenticator), nil
 }
 
 // untrustedIssuer extracts an untrusted "iss" claim from the given JWT token,

plugin/pkg/authenticator/token/oidc/oidc_test.go

@@ -42,6 +42,7 @@ import (
 	"k8s.io/apiserver/pkg/server/dynamiccertificates"
 	utilfeature "k8s.io/apiserver/pkg/util/feature"
 	featuregatetesting "k8s.io/component-base/featuregate/testing"
+	"k8s.io/component-base/metrics/testutil"
 	"k8s.io/klog/v2"
 	"k8s.io/utils/pointer"
 )
@@ -2986,8 +2987,21 @@ func TestToken(t *testing.T) {
 			},
 		},
 	}
+
+	var successTestCount, failureTestCount int
 	for _, test := range tests {
 		t.Run(test.name, test.run)
+		if test.wantSkip || test.wantInitErr != "" {
+			continue
+		}
+		// check metrics for success and failure
+		if test.wantErr == "" {
+			successTestCount++
+			testutil.AssertHistogramTotalCount(t, "apiserver_authentication_jwt_authenticator_latency_seconds", map[string]string{"result": "success"}, successTestCount)
+		} else {
+			failureTestCount++
+			testutil.AssertHistogramTotalCount(t, "apiserver_authentication_jwt_authenticator_latency_seconds", map[string]string{"result": "failure"}, failureTestCount)
+		}
 	}
 }