Merge #151105

151105: pgwire: publish authentication latency internal metrics r=pritesh-lahoti a=souravcrl

Currently, we don't have a way of estimating how much time external authentication methods like ldap take for an auth attempt. With provisioning and authorization enabled, we will be adding additional latency for the auth flow. Hence, we need to gather additional metrics for enabling user auth:
 - Introduce a logging metric to complement auth_ldap_conn_latency cockroachdbMetric. This will be called auth.ldap.conn.latency.internal
 - This will be the actual auth time (authentication +provisioning + authorization) time. We will get the RTT times to the ldap server (bind service plus search user plus bind user plus search groups) and subtract it from the total auth time.

fixes #148874
Epic CRDB-21590

Release note(ops change): `auth.ldap.conn.latency.internal` has been added to denote the internal authentication time for ldap auth method.

Co-authored-by: souravcrl <[email protected]>

Author: craig[bot]

docs/generated/metrics/metrics.yaml

@@ -1136,6 +1136,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"
@@ -1084,6 +1085,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
@@ -1098,6 +1102,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 {
@@ -1138,6 +1145,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 {
@@ -1148,6 +1159,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
 	})
 
@@ -1184,6 +1198,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 {
@@ -1194,6 +1211,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)),
 	}
 }