Merge cockroachdb#124254

124254: pgwire: log session start and end unconditionally r=rafiss a=rafiss

### pgwire: remove redundant log for JWT auth

This already gets logged in the processCommands function, right before
the server enters the main command processing loop.

### pgwire: log auth info message as redactable string

Previously, the entire info text would be redacted, which made
debugging harder. This improves it so we use the built in
redaction facilities in order to get more detail.

### pgwire: log session start and end unconditionally

Release note (ops change): The client_authentication_ok and
client_session_end messages are now logged to the SESSIONS log channel
unconditionally. Previously, these would only be logged if the
server.auth_log.sql_sessions.enabled cluster setting was changed to
true. All other SESSIONS log messages are still only logged if
server.auth_log.sql_sessions.enabled or
server.auth_log.sql_connections.enabled are set to true.

If you do not want to see client_authentication_ok or client_session_end
messages, then the SESSIONS log channel can be disabled entirely.

fixes cockroachdb#122684


Co-authored-by: Rafi Shamim <rafi@cockroachlabs.com>

docs/generated/eventlog.md

@@ -2138,7 +2138,7 @@ Events of this type are only emitted when the cluster setting
 | Field | Description | Sensitive |
 |--|--|--|
 | `Method` | The authentication method used, once known. | no |
-| `Info` | The authentication progress message. | yes |
+| `Info` | The authentication progress message. | partially |
 
 
 #### Common fields

docs/generated/settings/settings-for-tenants.txt

@@ -74,8 +74,8 @@ schedules.backup.gc_protection.enabled	boolean	true	enable chaining of GC protec
 security.client_cert.subject_required.enabled	boolean	false	mandates a requirement for subject role to be set for db user	system-visible
 security.ocsp.mode	enumeration	off	use OCSP to check whether TLS certificates are revoked. If the OCSP server is unreachable, in strict mode all certificates will be rejected and in lax mode all certificates will be accepted. [off = 0, lax = 1, strict = 2]	application
 security.ocsp.timeout	duration	3s	timeout before considering the OCSP server unreachable	application
-server.auth_log.sql_connections.enabled	boolean	false	if set, log SQL client connect and disconnect events (note: may hinder performance on loaded nodes)	application
-server.auth_log.sql_sessions.enabled	boolean	false	if set, log SQL session login/disconnection events (note: may hinder performance on loaded nodes)	application
+server.auth_log.sql_connections.enabled	boolean	false	if set, log SQL client connect and disconnect events to the SESSIONS log channel (note: may hinder performance on loaded nodes)	application
+server.auth_log.sql_sessions.enabled	boolean	false	if set, log verbose SQL session authentication events to the SESSIONS log channel (note: may hinder performance on loaded nodes). Session start and end events are always logged regardless of this setting; disable the SESSIONS log channel to suppress them.	application
 server.authentication_cache.enabled	boolean	true	enables a cache used during authentication to avoid lookups to system tables when retrieving per-user authentication-related information	application
 server.child_metrics.enabled	boolean	false	enables the exporting of child metrics, additional prometheus time series with extra labels	application
 server.client_cert_expiration_cache.capacity	integer	1000	the maximum number of client cert expirations stored	application

docs/generated/settings/settings.html

@@ -101,8 +101,8 @@
 <tr><td><div id="setting-security-client-cert-subject-required-enabled" class="anchored"><code>security.client_cert.subject_required.enabled</code></div></td><td>boolean</td><td><code>false</code></td><td>mandates a requirement for subject role to be set for db user</td><td>Dedicated/Self-hosted (read-write); Serverless (read-only)</td></tr>
 <tr><td><div id="setting-security-ocsp-mode" class="anchored"><code>security.ocsp.mode</code></div></td><td>enumeration</td><td><code>off</code></td><td>use OCSP to check whether TLS certificates are revoked. If the OCSP server is unreachable, in strict mode all certificates will be rejected and in lax mode all certificates will be accepted. [off = 0, lax = 1, strict = 2]</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-security-ocsp-timeout" class="anchored"><code>security.ocsp.timeout</code></div></td><td>duration</td><td><code>3s</code></td><td>timeout before considering the OCSP server unreachable</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
-<tr><td><div id="setting-server-auth-log-sql-connections-enabled" class="anchored"><code>server.auth_log.sql_connections.enabled</code></div></td><td>boolean</td><td><code>false</code></td><td>if set, log SQL client connect and disconnect events (note: may hinder performance on loaded nodes)</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
-<tr><td><div id="setting-server-auth-log-sql-sessions-enabled" class="anchored"><code>server.auth_log.sql_sessions.enabled</code></div></td><td>boolean</td><td><code>false</code></td><td>if set, log SQL session login/disconnection events (note: may hinder performance on loaded nodes)</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
+<tr><td><div id="setting-server-auth-log-sql-connections-enabled" class="anchored"><code>server.auth_log.sql_connections.enabled</code></div></td><td>boolean</td><td><code>false</code></td><td>if set, log SQL client connect and disconnect events to the SESSIONS log channel (note: may hinder performance on loaded nodes)</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
+<tr><td><div id="setting-server-auth-log-sql-sessions-enabled" class="anchored"><code>server.auth_log.sql_sessions.enabled</code></div></td><td>boolean</td><td><code>false</code></td><td>if set, log verbose SQL session authentication events to the SESSIONS log channel (note: may hinder performance on loaded nodes). Session start and end events are always logged regardless of this setting; disable the SESSIONS log channel to suppress them.</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-server-authentication-cache-enabled" class="anchored"><code>server.authentication_cache.enabled</code></div></td><td>boolean</td><td><code>true</code></td><td>enables a cache used during authentication to avoid lookups to system tables when retrieving per-user authentication-related information</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-server-child-metrics-enabled" class="anchored"><code>server.child_metrics.enabled</code></div></td><td>boolean</td><td><code>false</code></td><td>enables the exporting of child metrics, additional prometheus time series with extra labels</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-server-client-cert-expiration-cache-capacity" class="anchored"><code>server.client_cert_expiration_cache.capacity</code></div></td><td>integer</td><td><code>1000</code></td><td>the maximum number of client cert expirations stored</td><td>Serverless/Dedicated/Self-Hosted</td></tr>

pkg/sql/pgwire/auth.go

@@ -13,10 +13,10 @@ package pgwire
 import (
 	"context"
 	"crypto/tls"
-	"fmt"
 	"net"
 	"strings"
 	"sync"
+	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/security"
 	"github.com/cockroachdb/cockroach/pkg/security/username"
@@ -29,6 +29,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/sessiondatapb"
 	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/log/eventpb"
+	"github.com/cockroachdb/cockroach/pkg/util/log/logpb"
 	"github.com/cockroachdb/errors"
 	"github.com/cockroachdb/redact"
 )
@@ -105,7 +106,7 @@ func (c *conn) handleAuthentication(
 	}
 
 	ac.SetAuthMethod(hbaEntry.Method.String())
-	ac.LogAuthInfof(ctx, "HBA rule: %s", hbaEntry.Input)
+	ac.LogAuthInfof(ctx, redact.Sprintf("HBA rule: %s", hbaEntry.Input))
 
 	// Populate the AuthMethod with per-connection information so that it
 	// can compose the next layer of behaviors that we're going to apply
@@ -415,11 +416,13 @@ type AuthConn interface {
 	SetSystemIdentity(systemIdentity username.SQLUsername)
 	// LogAuthInfof logs details about the progress of the
 	// authentication.
-	LogAuthInfof(ctx context.Context, format string, args ...interface{})
+	LogAuthInfof(ctx context.Context, msg redact.RedactableString)
 	// LogAuthFailed logs details about an authentication failure.
 	LogAuthFailed(ctx context.Context, reason eventpb.AuthFailReason, err error)
 	// LogAuthOK logs when the authentication handshake has completed.
 	LogAuthOK(ctx context.Context)
+	// LogSessionEnd logs when the session is ended.
+	LogSessionEnd(ctx context.Context, endTime time.Time)
 	// GetTenantSpecificMetrics returns the tenant-specific metrics for the connection.
 	GetTenantSpecificMetrics() *tenantSpecificMetrics
 }
@@ -521,28 +524,37 @@ func (p *authPipe) SetSystemIdentity(systemIdentity username.SQLUsername) {
 }
 
 func (p *authPipe) LogAuthOK(ctx context.Context) {
-	if p.log {
-		ev := &eventpb.ClientAuthenticationOk{
-			CommonConnectionDetails: p.connDetails,
-			CommonSessionDetails:    p.authDetails,
-			Method:                  p.authMethod,
-		}
-		log.StructuredEvent(ctx, ev)
+	// Logged unconditionally.
+	ev := &eventpb.ClientAuthenticationOk{
+		CommonConnectionDetails: p.connDetails,
+		CommonSessionDetails:    p.authDetails,
+		Method:                  p.authMethod,
 	}
+	log.StructuredEvent(ctx, ev)
 }
 
-func (p *authPipe) LogAuthInfof(ctx context.Context, format string, args ...interface{}) {
+func (p *authPipe) LogAuthInfof(ctx context.Context, msg redact.RedactableString) {
 	if p.log {
 		ev := &eventpb.ClientAuthenticationInfo{
 			CommonConnectionDetails: p.connDetails,
 			CommonSessionDetails:    p.authDetails,
-			Info:                    fmt.Sprintf(format, args...),
+			Info:                    msg,
 			Method:                  p.authMethod,
 		}
 		log.StructuredEvent(ctx, ev)
 	}
 }
 
+func (p *authPipe) LogSessionEnd(ctx context.Context, endTime time.Time) {
+	// Logged unconditionally.
+	ev := &eventpb.ClientSessionEnd{
+		CommonEventDetails:      logpb.CommonEventDetails{Timestamp: endTime.UnixNano()},
+		CommonConnectionDetails: p.connDetails,
+		Duration:                endTime.Sub(p.c.startTime).Nanoseconds(),
+	}
+	log.StructuredEvent(ctx, ev)
+}
+
 func (p *authPipe) LogAuthFailed(
 	ctx context.Context, reason eventpb.AuthFailReason, detailedErr error,
 ) {

pkg/sql/pgwire/auth_methods.go

@@ -34,6 +34,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/log/eventpb"
 	"github.com/cockroachdb/cockroach/pkg/util/uuid"
 	"github.com/cockroachdb/errors"
+	"github.com/cockroachdb/redact"
 	"github.com/go-ldap/ldap/v3"
 	"github.com/xdg-go/scram"
 )
@@ -353,7 +354,7 @@ func scramAuthenticator(
 				return err
 			}
 			if reqMethod != "SCRAM-SHA-256" {
-				c.LogAuthInfof(ctx, "client requests unknown scram method %q", reqMethod)
+				c.LogAuthInfof(ctx, redact.Sprintf("client requests unknown scram method %q", redact.SafeString(reqMethod)))
 				err := unimplemented.NewWithIssue(74300, "channel binding not supported")
 				// We need to manually report the unimplemented error because it is not
 				// passed through to the client as-is (authn errors are hidden behind
@@ -785,7 +786,6 @@ func authJwtToken(
 				errors.Join(authError, errors.Newf("%s", detailedErrors)))
 			return authError
 		}
-		c.LogAuthOK(ctx)
 		return nil
 	})
 	return b, nil

pkg/sql/pgwire/conn.go

@@ -134,8 +134,8 @@ func (c *conn) sendError(ctx context.Context, err error) error {
 	return err
 }
 
-func (c *conn) authLogEnabled() bool {
-	return c.alwaysLogAuthActivity || logSessionAuth.Get(c.sv)
+func (c *conn) verboseAuthLogEnabled() bool {
+	return c.alwaysLogAuthActivity || logVerboseSessionAuth.Get(c.sv)
 }
 
 // processCommands authenticates the connection and then processes commands

pkg/sql/pgwire/server.go

@@ -80,14 +80,18 @@ var connResultsBufferSize = settings.RegisterByteSizeSetting(
 var logConnAuth = settings.RegisterBoolSetting(
 	settings.ApplicationLevel,
 	sql.ConnAuditingClusterSettingName,
-	"if set, log SQL client connect and disconnect events (note: may hinder performance on loaded nodes)",
+	"if set, log SQL client connect and disconnect events to the SESSIONS log channel "+
+		"(note: may hinder performance on loaded nodes)",
 	false,
 	settings.WithPublic)
 
-var logSessionAuth = settings.RegisterBoolSetting(
+var logVerboseSessionAuth = settings.RegisterBoolSetting(
 	settings.ApplicationLevel,
 	sql.AuthAuditingClusterSettingName,
-	"if set, log SQL session login/disconnection events (note: may hinder performance on loaded nodes)",
+	"if set, log verbose SQL session authentication events to the SESSIONS log channel "+
+		"(note: may hinder performance on loaded nodes). "+
+		"Session start and end events are always logged regardless of this setting; "+
+		"disable the SESSIONS log channel to suppress them.",
 	false,
 	settings.WithPublic)
 
@@ -950,35 +954,25 @@ func (s *Server) serveImpl(
 
 	sqlServer := s.SQLServer
 	inTestWithoutSQL := sqlServer == nil
-	if !inTestWithoutSQL {
-		sessionStart := timeutil.Now()
-		defer func() {
-			if c.authLogEnabled() {
-				endTime := timeutil.Now()
-				ev := &eventpb.ClientSessionEnd{
-					CommonEventDetails:      logpb.CommonEventDetails{Timestamp: endTime.UnixNano()},
-					CommonConnectionDetails: authOpt.connDetails,
-					Duration:                endTime.Sub(sessionStart).Nanoseconds(),
-				}
-				log.StructuredEvent(ctx, ev)
-			}
-		}()
-	}
 
 	// NOTE: We're going to write a few messages to the connection in this method,
 	// for the handshake. After that, all writes are done async, in the
 	// startWriter() goroutine.
 
-	// the authPipe below logs authentication messages iff its auth
-	// logger is non-nil. We define this here.
-	logAuthn := !inTestWithoutSQL && c.authLogEnabled()
-
 	// We'll build an authPipe to communicate with the authentication process.
 	systemIdentity := c.sessionArgs.SystemIdentity
 	if systemIdentity.Undefined() {
 		systemIdentity = c.sessionArgs.User
 	}
-	authPipe := newAuthPipe(c, logAuthn, authOpt, systemIdentity)
+	logVerboseAuthn := !inTestWithoutSQL && c.verboseAuthLogEnabled()
+	authPipe := newAuthPipe(c, logVerboseAuthn, authOpt, systemIdentity)
+
+	if !inTestWithoutSQL {
+		defer func() {
+			endTime := timeutil.Now()
+			authPipe.LogSessionEnd(ctx, endTime)
+		}()
+	}
 
 	// procWg waits for the command processor to return.
 	var procWg sync.WaitGroup

pkg/util/log/eventpb/session_events.proto

@@ -170,5 +170,5 @@ message ClientAuthenticationInfo {
   // The authentication method used, once known.
   string method = 4 [(gogoproto.jsontag) = ",omitempty", (gogoproto.moretags) = "redact:\"nonsensitive\""];
   // The authentication progress message.
-  string info = 5 [(gogoproto.jsontag) = ",omitempty"];
+  string info = 5 [(gogoproto.jsontag) = ",omitempty", (gogoproto.customtype) = "github.com/cockroachdb/redact.RedactableString", (gogoproto.nullable) = false, (gogoproto.moretags) = "redact:\"mixed\""];
 }