feat: expose context to debug logger (#797)

Co-authored-by: Eno Compton <[email protected]>
Co-authored-by: Jack Wotherspoon <[email protected]>

README.md

@@ -432,7 +432,7 @@ It shouldn't impact database operations.
 
 The Go Connector supports optional debug logging to help diagnose problems with
 the background certificate refresh. To enable it, provide a logger that
-implements the `debug.Logger` interface when initializing the Dialer.
+implements the `debug.ContextLogger` interface when initializing the Dialer.
 
 For example:
 
@@ -446,7 +446,7 @@ import (
 
 type myLogger struct{}
 
-func (l *myLogger) Debugf(format string, args ...interface{}) {
+func (l *myLogger) Debugf(ctx context.Context, format string, args ...interface{}) {
     // Log as you like here
 }
 
@@ -455,7 +455,7 @@ func connect() {
 
     d, err := NewDialer(
         context.Background(),
-        cloudsqlconn.WithDebugLogger(l),
+        cloudsqlconn.WithContextDebugLogger(l),
     )
     // use dialer as usual...
 }

debug/debug.go

@@ -14,8 +14,18 @@
 
 package debug
 
+import "context"
+
 // Logger is the interface used for debug logging. By default, it is unused.
+//
+// Prefer ContextLogger instead.
 type Logger interface {
 	// Debugf is for reporting information about internal operations.
 	Debugf(format string, args ...interface{})
 }
+
+// ContextLogger is the interface used for debug logging. By default, it is unused.
+type ContextLogger interface {
+	// Debugf is for reporting information about internal operations.
+	Debugf(ctx context.Context, format string, args ...interface{})
+}

dialer.go

@@ -101,7 +101,7 @@ type Dialer struct {
 	closed chan struct{}
 
 	sqladmin *sqladmin.Service
-	logger   debug.Logger
+	logger   debug.ContextLogger
 
 	// lazyRefresh determines what kind of caching is used for ephemeral
 	// certificates. When lazyRefresh is true, the dialer will use a lazy
@@ -133,7 +133,7 @@ var (
 
 type nullLogger struct{}
 
-func (nullLogger) Debugf(_ string, _ ...interface{}) {}
+func (nullLogger) Debugf(_ context.Context, _ string, _ ...interface{}) {}
 
 // NewDialer creates a new Dialer.
 //
@@ -272,12 +272,12 @@ func (d *Dialer) Dial(ctx context.Context, icn string, opts ...DialOption) (conn
 
 	var endInfo trace.EndSpanFunc
 	ctx, endInfo = trace.StartSpan(ctx, "cloud.google.com/go/cloudsqlconn/internal.InstanceInfo")
-	c := d.connectionInfoCache(cn, &cfg.useIAMAuthN)
+	c := d.connectionInfoCache(ctx, cn, &cfg.useIAMAuthN)
 	ci, err := c.ConnectionInfo(ctx)
 	if err != nil {
 		d.lock.Lock()
 		defer d.lock.Unlock()
-		d.logger.Debugf("[%v] Removing connection info from cache", cn.String())
+		d.logger.Debugf(ctx, "[%v] Removing connection info from cache", cn.String())
 		// Stop all background refreshes
 		c.Close()
 		delete(d.cache, cn)
@@ -291,15 +291,15 @@ func (d *Dialer) Dial(ctx context.Context, icn string, opts ...DialOption) (conn
 	// The TLS handshake will not fail on an expired client certificate. It's
 	// not until the first read where the client cert error will be surfaced.
 	// So check that the certificate is valid before proceeding.
-	if !validClientCert(cn, d.logger, ci.Expiration) {
-		d.logger.Debugf("[%v] Refreshing certificate now", cn.String())
+	if !validClientCert(ctx, cn, d.logger, ci.Expiration) {
+		d.logger.Debugf(ctx, "[%v] Refreshing certificate now", cn.String())
 		c.ForceRefresh()
 		// Block on refreshed connection info
 		ci, err = c.ConnectionInfo(ctx)
 		if err != nil {
 			d.lock.Lock()
 			defer d.lock.Unlock()
-			d.logger.Debugf("[%v] Removing connection info from cache", cn.String())
+			d.logger.Debugf(ctx, "[%v] Removing connection info from cache", cn.String())
 			// Stop all background refreshes
 			c.Close()
 			delete(d.cache, cn)
@@ -319,10 +319,10 @@ func (d *Dialer) Dial(ctx context.Context, icn string, opts ...DialOption) (conn
 	if cfg.dialFunc != nil {
 		f = cfg.dialFunc
 	}
-	d.logger.Debugf("[%v] Dialing %v", cn.String(), addr)
+	d.logger.Debugf(ctx, "[%v] Dialing %v", cn.String(), addr)
 	conn, err = f(ctx, "tcp", addr)
 	if err != nil {
-		d.logger.Debugf("[%v] Dialing %v failed: %v", cn.String(), addr, err)
+		d.logger.Debugf(ctx, "[%v] Dialing %v failed: %v", cn.String(), addr, err)
 		// refresh the instance info in case it caused the connection failure
 		c.ForceRefresh()
 		return nil, errtype.NewDialError("failed to dial", cn.String(), err)
@@ -339,7 +339,7 @@ func (d *Dialer) Dial(ctx context.Context, icn string, opts ...DialOption) (conn
 	tlsConn := tls.Client(conn, ci.TLSConfig())
 	err = tlsConn.HandshakeContext(ctx)
 	if err != nil {
-		d.logger.Debugf("[%v] TLS handshake failed: %v", cn.String(), err)
+		d.logger.Debugf(ctx, "[%v] TLS handshake failed: %v", cn.String(), err)
 		// refresh the instance info in case it caused the handshake failure
 		c.ForceRefresh()
 		_ = tlsConn.Close() // best effort close attempt
@@ -362,20 +362,21 @@ func (d *Dialer) Dial(ctx context.Context, icn string, opts ...DialOption) (conn
 // validClientCert checks that the ephemeral client certificate retrieved from
 // the cache is unexpired. The time comparisons strip the monotonic clock value
 // to ensure an accurate result, even after laptop sleep.
-func validClientCert(cn instance.ConnName, l debug.Logger, expiration time.Time) bool {
+func validClientCert(ctx context.Context, cn instance.ConnName, l debug.ContextLogger, expiration time.Time) bool {
 	// Use UTC() to strip monotonic clock value to guard against inaccurate
 	// comparisons, especially after laptop sleep.
 	// See the comments on the monotonic clock in the Go documentation for
 	// details: https://pkg.go.dev/time#hdr-Monotonic_Clocks
 	now := time.Now().UTC()
 	valid := expiration.UTC().After(now)
 	l.Debugf(
+		ctx,
 		"[%v] Now = %v, Current cert expiration = %v",
 		cn.String(),
 		now.Format(time.RFC3339),
 		expiration.UTC().Format(time.RFC3339),
 	)
-	l.Debugf("[%v] Cert is valid = %v", cn.String(), valid)
+	l.Debugf(ctx, "[%v] Cert is valid = %v", cn.String(), valid)
 	return valid
 }
 
@@ -388,7 +389,7 @@ func (d *Dialer) EngineVersion(ctx context.Context, icn string) (string, error)
 	if err != nil {
 		return "", err
 	}
-	i := d.connectionInfoCache(cn, nil)
+	i := d.connectionInfoCache(ctx, cn, nil)
 	ci, err := i.ConnectionInfo(ctx)
 	if err != nil {
 		return "", err
@@ -399,7 +400,7 @@ func (d *Dialer) EngineVersion(ctx context.Context, icn string) (string, error)
 // Warmup starts the background refresh necessary to connect to the instance.
 // Use Warmup to start the refresh process early if you don't know when you'll
 // need to call "Dial".
-func (d *Dialer) Warmup(_ context.Context, icn string, opts ...DialOption) error {
+func (d *Dialer) Warmup(ctx context.Context, icn string, opts ...DialOption) error {
 	cn, err := instance.ParseConnName(icn)
 	if err != nil {
 		return err
@@ -408,7 +409,7 @@ func (d *Dialer) Warmup(_ context.Context, icn string, opts ...DialOption) error
 	for _, opt := range opts {
 		opt(&cfg)
 	}
-	_ = d.connectionInfoCache(cn, &cfg.useIAMAuthN)
+	_ = d.connectionInfoCache(ctx, cn, &cfg.useIAMAuthN)
 	return nil
 }
 
@@ -461,7 +462,7 @@ func (d *Dialer) Close() error {
 // connection info Cache in a threadsafe way. It will create a new cache,
 // modify the existing one, or leave it unchanged as needed.
 func (d *Dialer) connectionInfoCache(
-	cn instance.ConnName, useIAMAuthN *bool,
+	ctx context.Context, cn instance.ConnName, useIAMAuthN *bool,
 ) monitoredCache {
 	d.lock.RLock()
 	c, ok := d.cache[cn]
@@ -476,7 +477,7 @@ func (d *Dialer) connectionInfoCache(
 			if useIAMAuthN != nil {
 				useIAMAuthNDial = *useIAMAuthN
 			}
-			d.logger.Debugf("[%v] Connection info added to cache", cn.String())
+			d.logger.Debugf(ctx, "[%v] Connection info added to cache", cn.String())
 			var cache connectionInfoCache
 			if d.lazyRefresh {
 				cache = cloudsql.NewLazyRefreshCache(

internal/cloudsql/instance.go

@@ -92,7 +92,7 @@ type RefreshAheadCache struct {
 	openConns uint64
 
 	connName instance.ConnName
-	logger   debug.Logger
+	logger   debug.ContextLogger
 	key      *rsa.PrivateKey
 
 	// refreshTimeout sets the maximum duration a refresh cycle can run
@@ -121,7 +121,7 @@ type RefreshAheadCache struct {
 // NewRefreshAheadCache initializes a new Instance given an instance connection name
 func NewRefreshAheadCache(
 	cn instance.ConnName,
-	l debug.Logger,
+	l debug.ContextLogger,
 	client *sqladmin.Service,
 	key *rsa.PrivateKey,
 	refreshTimeout time.Duration,
@@ -366,6 +366,7 @@ func (i *RefreshAheadCache) scheduleRefresh(d time.Duration) *refreshOperation {
 		// instance has been closed, don't schedule anything
 		if err := i.ctx.Err(); err != nil {
 			i.logger.Debugf(
+				context.Background(),
 				"[%v] Instance is closed, stopping refresh operations",
 				i.connName.String(),
 			)
@@ -374,6 +375,7 @@ func (i *RefreshAheadCache) scheduleRefresh(d time.Duration) *refreshOperation {
 			return
 		}
 		i.logger.Debugf(
+			context.Background(),
 			"[%v] Connection info refresh operation started",
 			i.connName.String(),
 		)
@@ -397,16 +399,19 @@ func (i *RefreshAheadCache) scheduleRefresh(d time.Duration) *refreshOperation {
 		switch r.err {
 		case nil:
 			i.logger.Debugf(
+				ctx,
 				"[%v] Connection info refresh operation complete",
 				i.connName.String(),
 			)
 			i.logger.Debugf(
+				ctx,
 				"[%v] Current certificate expiration = %v",
 				i.connName.String(),
 				r.result.Expiration.UTC().Format(time.RFC3339),
 			)
 		default:
 			i.logger.Debugf(
+				ctx,
 				"[%v] Connection info refresh operation failed, err = %v",
 				i.connName.String(),
 				r.err,
@@ -423,6 +428,7 @@ func (i *RefreshAheadCache) scheduleRefresh(d time.Duration) *refreshOperation {
 		// if failed, scheduled the next refresh immediately
 		if r.err != nil {
 			i.logger.Debugf(
+				ctx,
 				"[%v] Connection info refresh operation scheduled immediately",
 				i.connName.String(),
 			)
@@ -444,6 +450,7 @@ func (i *RefreshAheadCache) scheduleRefresh(d time.Duration) *refreshOperation {
 		i.cur = r
 		t := refreshDuration(time.Now(), i.cur.result.Expiration)
 		i.logger.Debugf(
+			ctx,
 			"[%v] Connection info refresh operation scheduled at %v (now + %v)",
 			i.connName.String(),
 			time.Now().Add(t).UTC().Format(time.RFC3339),

internal/cloudsql/instance_test.go

@@ -32,7 +32,7 @@ import (
 
 type nullLogger struct{}
 
-func (nullLogger) Debugf(string, ...interface{}) {}
+func (nullLogger) Debugf(context.Context, string, ...interface{}) {}
 
 // genRSAKey generates an RSA key used for test.
 func genRSAKey() *rsa.PrivateKey {

internal/cloudsql/lazy.go

@@ -30,7 +30,7 @@ import (
 // a caller requests connection info and the current certificate is expired.
 type LazyRefreshCache struct {
 	connName        instance.ConnName
-	logger          debug.Logger
+	logger          debug.ContextLogger
 	key             *rsa.PrivateKey
 	r               refresher
 	mu              sync.Mutex
@@ -42,7 +42,7 @@ type LazyRefreshCache struct {
 // NewLazyRefreshCache initializes a new LazyRefreshCache.
 func NewLazyRefreshCache(
 	cn instance.ConnName,
-	l debug.Logger,
+	l debug.ContextLogger,
 	client *sqladmin.Service,
 	key *rsa.PrivateKey,
 	_ time.Duration,
@@ -80,30 +80,35 @@ func (c *LazyRefreshCache) ConnectionInfo(
 	exp := c.cached.Expiration.UTC().Add(-refreshBuffer)
 	if !c.needsRefresh && now.Before(exp) {
 		c.logger.Debugf(
+			ctx,
 			"[%v] Connection info is still valid, using cached info",
 			c.connName.String(),
 		)
 		return c.cached, nil
 	}
 
 	c.logger.Debugf(
+		ctx,
 		"[%v] Connection info refresh operation started",
 		c.connName.String(),
 	)
 	ci, err := c.r.ConnectionInfo(ctx, c.connName, c.key, c.useIAMAuthNDial)
 	if err != nil {
 		c.logger.Debugf(
+			ctx,
 			"[%v] Connection info refresh operation failed, err = %v",
 			c.connName.String(),
 			err,
 		)
 		return ConnectionInfo{}, err
 	}
 	c.logger.Debugf(
+		ctx,
 		"[%v] Connection info refresh operation complete",
 		c.connName.String(),
 	)
 	c.logger.Debugf(
+		ctx,
 		"[%v] Current certificate expiration = %v",
 		c.connName.String(),
 		ci.Expiration.UTC().Format(time.RFC3339),

internal/cloudsql/refresh.go

@@ -234,7 +234,7 @@ func fetchEphemeralCert(
 
 // newRefresher creates a Refresher.
 func newRefresher(
-	l debug.Logger,
+	l debug.ContextLogger,
 	svc *sqladmin.Service,
 	ts oauth2.TokenSource,
 	dialerID string,
@@ -252,7 +252,7 @@ func newRefresher(
 type refresher struct {
 	// dialerID is the unique ID of the associated dialer.
 	dialerID string
-	logger   debug.Logger
+	logger   debug.ContextLogger
 	client   *sqladmin.Service
 	// ts is the TokenSource used for IAM DB AuthN.
 	ts oauth2.TokenSource

options.go

@@ -41,7 +41,7 @@ type dialerConfig struct {
 	dialFunc               func(ctx context.Context, network, addr string) (net.Conn, error)
 	refreshTimeout         time.Duration
 	useIAMAuthN            bool
-	logger                 debug.Logger
+	logger                 debug.ContextLogger
 	lazyRefresh            bool
 	iamLoginTokenSource    oauth2.TokenSource
 	useragents             []string
@@ -234,9 +234,30 @@ func WithIAMAuthN() Option {
 	}
 }
 
+type debugLoggerWithoutContext struct {
+	logger debug.Logger
+}
+
+// Debugf implements debug.ContextLogger.
+func (d *debugLoggerWithoutContext) Debugf(_ context.Context, format string, args ...interface{}) {
+	d.logger.Debugf(format, args...)
+}
+
+var _ debug.ContextLogger = new(debugLoggerWithoutContext)
+
 // WithDebugLogger configures a debug lgoger for reporting on internal
 // operations. By default the debug logger is disabled.
+//
+// Deprecated: use WithContextDebugLogger instead
 func WithDebugLogger(l debug.Logger) Option {
+	return func(d *dialerConfig) {
+		d.logger = &debugLoggerWithoutContext{l}
+	}
+}
+
+// WithContextDebugLogger configures a debug logger for reporting on internal
+// operations. By default the debug logger is disabled.
+func WithContextDebugLogger(l debug.ContextLogger) Option {
 	return func(d *dialerConfig) {
 		d.logger = l
 	}