Merge pull request #152341 from souravcrl/blathers/backport-release-25.3-151105

release-25.3: pgwire: publish authentication latency internal metrics

Author: souravcrl

docs/generated/metrics/metrics.yaml

@@ -864,6 +864,14 @@ layers:
       unit: NANOSECONDS
       aggregation: AVG
       derivative: NONE
+    - name: auth.ldap.conn.latency.internal
+      exported_name: auth_ldap_conn_latency_internal
+      description: Internal Auth Latency to establish and authenticate a SQL connection using LDAP(excludes external LDAP calls)
+      y_axis_label: Nanoseconds
+      type: HISTOGRAM
+      unit: NANOSECONDS
+      aggregation: AVG
+      derivative: NONE
     - name: auth.password.conn.latency
       exported_name: auth_password_conn_latency
       description: Latency to establish and authenticate a SQL connection using password

pkg/sql/pgwire/auth.go

@@ -281,6 +281,17 @@ func (c *conn) handleAuthentication(
 	duration := timeutil.Since(authStartTime).Nanoseconds()
 	c.publishConnLatencyMetric(duration, hbaEntry.Method.String())
 
+	// Get the external auth duration which is time spent on external service by
+	// the AuthMethod.
+	externalDuration := behaviors.GetTotalExternalAuthTime().Nanoseconds()
+
+	// Compute the internal authentication latency needed to serve a SQL query.
+	// The internal latency is the time spent on the connection for the actual
+	// auth time (authentication +provisioning + authorization) time. We will get
+	// the RTT times to the IDP server and subtract it from the total auth time.
+	// The metric published is based on the authentication type.
+	c.publishConnLatencyInternalMetric(duration-externalDuration, hbaEntry.Method.String())
+
 	server.lastLoginUpdater.updateLastLoginTime(ctx, dbUser)
 
 	return connClose, nil
@@ -305,6 +316,15 @@ func (c *conn) publishConnLatencyMetric(duration int64, authMethod string) {
 	}
 }
 
+// publishConnLatencyInternalMetric publishes the internal latency of the
+// connection based on the authentication method.
+func (c *conn) publishConnLatencyInternalMetric(internalDuration int64, authMethod string) {
+	switch authMethod {
+	case ldapHBAEntry.string():
+		c.metrics.AuthLDAPConnLatencyInternal.RecordValue(internalDuration)
+	}
+}
+
 func (c *conn) authOKMessage() error {
 	c.msgBuilder.initMsg(pgwirebase.ServerMsgAuth)
 	c.msgBuilder.putInt32(authOK)

pkg/sql/pgwire/auth_behaviors.go

@@ -8,6 +8,7 @@ package pgwire
 import (
 	"context"
 	"sync"
+	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/security/provisioning"
 	"github.com/cockroachdb/cockroach/pkg/security/username"
@@ -33,7 +34,8 @@ type AuthBehaviors struct {
 		sync.Once
 		pc provisioning.UserProvisioningConfig
 	}
-	provisioner Provisioner
+	provisioner      Provisioner
+	externalAuthTime time.Duration
 }
 
 // Ensure that an AuthBehaviors is easily composable with itself.
@@ -178,3 +180,17 @@ func (b *AuthBehaviors) MaybeProvisionUser(
 	}
 	return nil
 }
+
+// AddExternalAuthTime adds a time duration to the externalAuthTime during auth.
+// The AuthMethod implementation adds new time durations which track time spent
+// where auth is waiting on a response from an external service like making an
+// API call or validating a response from an external service.
+func (b *AuthBehaviors) AddExternalAuthTime(t time.Duration) {
+	b.externalAuthTime += t
+}
+
+// GetTotalExternalAuthTime returns the total aggregated time spent on external
+// service during authentication.
+func (b *AuthBehaviors) GetTotalExternalAuthTime() time.Duration {
+	return b.externalAuthTime
+}

pkg/sql/pgwire/auth_methods.go

@@ -32,6 +32,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/errorutil/unimplemented"
 	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/log/eventpb"
+	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/cockroach/pkg/util/uuid"
 	"github.com/cockroachdb/errors"
 	"github.com/cockroachdb/redact"
@@ -987,6 +988,9 @@ func AuthLDAP(
 	b := &AuthBehaviors{}
 	b.SetRoleMapper(UseSpecifiedIdentity(sessionUser))
 
+	// Audit the lookup start time.
+	ldapLookupStartTime := timeutil.Now()
+
 	ldapUserDN, detailedErrors, authError := ldapManager.m.FetchLDAPUserDN(sCtx, execCfg.Settings, sessionUser, entry, identMap)
 	if authError != nil {
 		errForLog := authError
@@ -1001,6 +1005,9 @@ func AuthLDAP(
 		b.SetReplacementIdentity(ldapUserDN.String())
 	}
 
+	// Add the total lookup time to the external auth time.
+	b.AddExternalAuthTime(timeutil.Since(ldapLookupStartTime))
+
 	b.SetAuthenticator(func(
 		ctx context.Context, systemIdentity string, clientConnection bool, _ PasswordRetrievalFn, _ *ldap.DN,
 	) error {
@@ -1041,6 +1048,10 @@ func AuthLDAP(
 		if len(ldapPwd) == 0 {
 			return security.NewErrPasswordUserAuthFailed(sessionUser)
 		}
+
+		// Audit the authN start time.
+		ldapAuthNStartTime := timeutil.Now()
+
 		if detailedErrors, authError := ldapManager.m.ValidateLDAPLogin(
 			ctx, execCfg.Settings, ldapUserDN, sessionUser, ldapPwd, entry, identMap,
 		); authError != nil {
@@ -1051,6 +1062,9 @@ func AuthLDAP(
 			c.LogAuthFailed(ctx, eventpb.AuthFailReason_CREDENTIALS_INVALID, errForLog)
 			return authError
 		}
+
+		// Add the total authN time to the external auth time.
+		b.AddExternalAuthTime(timeutil.Since(ldapAuthNStartTime))
 		return nil
 	})
 
@@ -1087,6 +1101,9 @@ func AuthLDAP(
 				return err
 			}
 
+			// Audit the authZ start time.
+			ldapAuthZStartTime := timeutil.Now()
+
 			if ldapGroups, detailedErrors, authError := ldapManager.m.FetchLDAPGroups(
 				ctx, execCfg.Settings, ldapUserDN, sessionUser, entry, identMap,
 			); authError != nil {
@@ -1097,6 +1114,9 @@ func AuthLDAP(
 				c.LogAuthFailed(ctx, eventpb.AuthFailReason_AUTHORIZATION_ERROR, errForLog)
 				return authError
 			} else {
+				// Add the total authZ time to the external auth time.
+				b.AddExternalAuthTime(timeutil.Since(ldapAuthZStartTime))
+
 				c.LogAuthInfof(ctx, redact.Sprintf("LDAP authorization sync succeeded; attempting to assign roles for LDAP groups: %s", ldapGroups))
 				// Parse and apply transformation to LDAP group DNs for roles granter.
 				sqlRoles := make([]username.SQLUsername, 0, len(ldapGroups))

pkg/sql/pgwire/conn_test.go

@@ -2303,6 +2303,8 @@ func TestPublishConnLatencyMetric(t *testing.T) {
 				getHistogramOptionsForIOLatency(AuthGSSConnLatency, time.Hour)),
 			AuthScramConnLatency: metric.NewHistogram(
 				getHistogramOptionsForIOLatency(AuthScramConnLatency, time.Hour)),
+			AuthLDAPConnLatencyInternal: metric.NewHistogram(
+				getHistogramOptionsForIOLatency(AuthLDAPConnLatencyInternal, time.Hour)),
 		},
 	}
 
@@ -2402,3 +2404,53 @@ func TestPublishConnLatencyMetric(t *testing.T) {
 	require.Equal(t, int64(2), count)
 	require.Equal(t, float64(9), sum)
 }
+
+// write unit tests for the function publishConnLatencyInternalMetric
+func TestPublishConnLatencyInternalMetric(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+
+	c := conn{
+		metrics: &tenantSpecificMetrics{
+			AuthLDAPConnLatency: metric.NewHistogram(
+				getHistogramOptionsForIOLatency(AuthLDAPConnLatency, time.Hour)),
+			AuthLDAPConnLatencyInternal: metric.NewHistogram(
+				getHistogramOptionsForIOLatency(AuthLDAPConnLatencyInternal, time.Hour)),
+		},
+	}
+
+	// LDAP
+	ldapDuration := int64(5)
+	ldapInternalDuration := int64(4)
+	c.publishConnLatencyMetric(ldapDuration, ldapHBAEntry.string())
+	c.publishConnLatencyInternalMetric(ldapInternalDuration, ldapHBAEntry.string())
+	w := c.metrics.AuthLDAPConnLatency.WindowedSnapshot()
+	count, sum := w.Total()
+	require.Equal(t, int64(1), count)
+	require.Equal(t, float64(5), sum)
+
+	wI := c.metrics.AuthLDAPConnLatencyInternal.WindowedSnapshot()
+	countI, sumI := wI.Total()
+	require.Equal(t, int64(1), countI)
+	require.Equal(t, float64(4), sumI)
+
+	// internal latency must be less than total latency.
+	require.Less(t, sumI, sum)
+
+	// republish on LDAP
+	ldapDuration = int64(2)
+	ldapInternalDuration = int64(1)
+	c.publishConnLatencyMetric(ldapDuration, ldapHBAEntry.string())
+	c.publishConnLatencyInternalMetric(ldapInternalDuration, ldapHBAEntry.string())
+	w = c.metrics.AuthLDAPConnLatency.WindowedSnapshot()
+	count, sum = w.Total()
+	require.Equal(t, int64(2), count)
+	require.Equal(t, float64(7), sum)
+
+	wI = c.metrics.AuthLDAPConnLatencyInternal.WindowedSnapshot()
+	countI, sumI = wI.Total()
+	require.Equal(t, int64(2), countI)
+	require.Equal(t, float64(5), sumI)
+
+	// internal latency must be less than total latency.
+	require.Less(t, sumI, sum)
+}

pkg/sql/pgwire/server.go

@@ -224,6 +224,12 @@ var (
 		Measurement: "Nanoseconds",
 		Unit:        metric.Unit_NANOSECONDS,
 	}
+	AuthLDAPConnLatencyInternal = metric.Metadata{
+		Name:        "auth.ldap.conn.latency.internal",
+		Help:        "Internal Auth Latency to establish and authenticate a SQL connection using LDAP(excludes external LDAP calls)",
+		Measurement: "Nanoseconds",
+		Unit:        metric.Unit_NANOSECONDS,
+	}
 )
 
 const (
@@ -377,6 +383,7 @@ type tenantSpecificMetrics struct {
 	AuthLDAPConnLatency         metric.IHistogram
 	AuthGSSConnLatency          metric.IHistogram
 	AuthScramConnLatency        metric.IHistogram
+	AuthLDAPConnLatencyInternal metric.IHistogram
 }
 
 func newTenantSpecificMetrics(
@@ -411,6 +418,8 @@ func newTenantSpecificMetrics(
 			getHistogramOptionsForIOLatency(AuthGSSConnLatency, histogramWindow)),
 		AuthScramConnLatency: metric.NewHistogram(
 			getHistogramOptionsForIOLatency(AuthScramConnLatency, histogramWindow)),
+		AuthLDAPConnLatencyInternal: metric.NewHistogram(
+			getHistogramOptionsForIOLatency(AuthLDAPConnLatencyInternal, histogramWindow)),
 	}
 }