feat: add context debug logger (#573)

Callers may now provide a context to correlate logs with trace IDs in
their implementation of the interface.

This is a port of GoogleCloudPlatform/cloud-sql-go-connector#797

Author: enocom

README.md

@@ -312,7 +312,7 @@ func main() {
 
 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:
 
@@ -326,7 +326,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
 }
 
@@ -335,7 +335,7 @@ func connect() {
 
     d, err := NewDialer(
         context.Background(),
-        alloydbconn.WithDebugLogger(l),
+        alloydbconn.WithContextDebugLogger(l),
     )
     // use dialer as usual...
 }

debug/debug.go

@@ -14,8 +14,17 @@
 
 package debug
 
+import "context"
+
 // Logger is the interface used for debug logging. By default, it is unused.
 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

@@ -111,7 +111,7 @@ type Dialer struct {
 	staticConnInfo io.Reader
 
 	client *alloydbadmin.AlloyDBAdminClient
-	logger debug.Logger
+	logger debug.ContextLogger
 
 	// defaultDialCfg holds the constructor level DialOptions, so that it can
 	// be copied and mutated by the Dial function.
@@ -134,7 +134,7 @@ type Dialer struct {
 
 type nullLogger struct{}
 
-func (nullLogger) Debugf(string, ...interface{}) {}
+func (nullLogger) Debugf(context.Context, string, ...interface{}) {}
 
 // NewDialer creates a new Dialer.
 //
@@ -242,14 +242,14 @@ func (d *Dialer) Dial(ctx context.Context, instance string, opts ...DialOption)
 
 	var endInfo trace.EndSpanFunc
 	ctx, endInfo = trace.StartSpan(ctx, "cloud.google.com/go/alloydbconn/internal.InstanceInfo")
-	cache, err := d.connectionInfoCache(inst)
+	cache, err := d.connectionInfoCache(ctx, inst)
 	if err != nil {
 		endInfo(err)
 		return nil, err
 	}
 	ci, err := cache.ConnectionInfo(ctx)
 	if err != nil {
-		d.removeCached(inst, cache, err)
+		d.removeCached(ctx, inst, cache, err)
 		endInfo(err)
 		return nil, err
 	}
@@ -260,19 +260,19 @@ func (d *Dialer) Dial(ctx context.Context, instance string, opts ...DialOption)
 	// 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 invalidClientCert(inst, d.logger, ci.Expiration) {
-		d.logger.Debugf("[%v] Refreshing certificate now", inst.String())
+	if invalidClientCert(ctx, inst, d.logger, ci.Expiration) {
+		d.logger.Debugf(ctx, "[%v] Refreshing certificate now", inst.String())
 		cache.ForceRefresh()
 		// Block on refreshed connection info
 		ci, err = cache.ConnectionInfo(ctx)
 		if err != nil {
-			d.removeCached(inst, cache, err)
+			d.removeCached(ctx, inst, cache, err)
 			return nil, err
 		}
 	}
 	addr, ok := ci.IPAddrs[cfg.ipType]
 	if !ok {
-		d.removeCached(inst, cache, err)
+		d.removeCached(ctx, inst, cache, err)
 		err := errtype.NewConfigError(
 			fmt.Sprintf("instance does not have IP of type %q", cfg.ipType),
 			inst.String(),
@@ -288,10 +288,10 @@ func (d *Dialer) Dial(ctx context.Context, instance string, opts ...DialOption)
 	if cfg.dialFunc != nil {
 		f = cfg.dialFunc
 	}
-	d.logger.Debugf("[%v] Dialing %v", inst.String(), hostPort)
+	d.logger.Debugf(ctx, "[%v] Dialing %v", inst.String(), hostPort)
 	conn, err = f(ctx, "tcp", hostPort)
 	if err != nil {
-		d.logger.Debugf("[%v] Dialing %v failed: %v", inst.String(), hostPort, err)
+		d.logger.Debugf(ctx, "[%v] Dialing %v failed: %v", inst.String(), hostPort, err)
 		// refresh the instance info in case it caused the connection failure
 		cache.ForceRefresh()
 		return nil, errtype.NewDialError("failed to dial", inst.String(), err)
@@ -328,7 +328,7 @@ func (d *Dialer) Dial(ctx context.Context, instance string, opts ...DialOption)
 	}
 	tlsConn := tls.Client(conn, c)
 	if err := tlsConn.HandshakeContext(ctx); err != nil {
-		d.logger.Debugf("[%v] TLS handshake failed: %v", inst.String(), err)
+		d.logger.Debugf(ctx, "[%v] TLS handshake failed: %v", inst.String(), err)
 		// refresh the instance info in case it caused the handshake failure
 		cache.ForceRefresh()
 		_ = tlsConn.Close() // best effort close attempt
@@ -359,9 +359,11 @@ func (d *Dialer) Dial(ctx context.Context, instance string, opts ...DialOption)
 // removeCached stops all background refreshes and deletes the connection
 // info cache from the map of caches.
 func (d *Dialer) removeCached(
+	ctx context.Context,
 	i alloydb.InstanceURI, c connectionInfoCache, err error,
 ) {
 	d.logger.Debugf(
+		ctx,
 		"[%v] Removing connection info from cache: %v",
 		i.String(),
 		err,
@@ -373,18 +375,20 @@ func (d *Dialer) removeCached(
 }
 
 func invalidClientCert(
-	inst alloydb.InstanceURI, l debug.Logger, expiration time.Time,
+	ctx context.Context,
+	inst alloydb.InstanceURI, l debug.ContextLogger, expiration time.Time,
 ) bool {
 	now := time.Now().UTC()
 	notAfter := expiration.UTC()
 	invalid := now.After(notAfter)
 	l.Debugf(
+		ctx,
 		"[%v] Now = %v, Current cert expiration = %v",
 		inst.String(),
 		now.Format(time.RFC3339),
 		notAfter.Format(time.RFC3339),
 	)
-	l.Debugf("[%v] Cert is valid = %v", inst.String(), !invalid)
+	l.Debugf(ctx, "[%v] Cert is valid = %v", inst.String(), !invalid)
 	return invalid
 }
 
@@ -550,7 +554,7 @@ func (d *Dialer) Close() error {
 }
 
 func (d *Dialer) connectionInfoCache(
-	uri alloydb.InstanceURI,
+	ctx context.Context, uri alloydb.InstanceURI,
 ) (monitoredCache, error) {
 	d.lock.RLock()
 	c, ok := d.cache[uri]
@@ -562,6 +566,7 @@ func (d *Dialer) connectionInfoCache(
 		c, ok = d.cache[uri]
 		if !ok {
 			d.logger.Debugf(
+				ctx,
 				"[%v] Connection info added to cache",
 				uri.String(),
 			)

internal/alloydb/instance.go

@@ -137,7 +137,7 @@ func (r *refreshOperation) isValid() bool {
 // expires (every ~56 minutes).
 type RefreshAheadCache struct {
 	instanceURI InstanceURI
-	logger      debug.Logger
+	logger      debug.ContextLogger
 	key         *rsa.PrivateKey
 	// refreshTimeout sets the maximum duration a refresh cycle can run
 	// for.
@@ -165,7 +165,7 @@ type RefreshAheadCache struct {
 // caches connection info.
 func NewRefreshAheadCache(
 	instance InstanceURI,
-	l debug.Logger,
+	l debug.ContextLogger,
 	client *alloydbadmin.AlloyDBAdminClient,
 	key *rsa.PrivateKey,
 	refreshTimeout time.Duration,
@@ -265,6 +265,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.instanceURI.String(),
 			)
@@ -273,6 +274,7 @@ func (i *RefreshAheadCache) scheduleRefresh(d time.Duration) *refreshOperation {
 			return
 		}
 		i.logger.Debugf(
+			context.Background(),
 			"[%v] Connection info refresh operation started",
 			i.instanceURI.String(),
 		)
@@ -288,17 +290,20 @@ func (i *RefreshAheadCache) scheduleRefresh(d time.Duration) *refreshOperation {
 				nil,
 			)
 			i.logger.Debugf(
+				ctx,
 				"[%v] Connection info refresh operation failed, err = %v",
 				i.instanceURI.String(),
 				r.err,
 			)
 		} else {
 			r.result, r.err = i.r.performRefresh(i.ctx, i.instanceURI, i.key)
 			i.logger.Debugf(
+				ctx,
 				"[%v] Connection info refresh operation complete",
 				i.instanceURI.String(),
 			)
 			i.logger.Debugf(
+				ctx,
 				"[%v] Current certificate expiration = %v",
 				i.instanceURI.String(),
 				r.result.Expiration.UTC().Format(time.RFC3339),
@@ -315,6 +320,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.instanceURI.String(),
 			)
@@ -335,6 +341,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.instanceURI.String(),
 			time.Now().Add(t).UTC().Format(time.RFC3339),

internal/alloydb/instance_test.go

@@ -31,7 +31,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/alloydb/lazy.go

@@ -28,7 +28,7 @@ import (
 // a caller requests connection info and the current certificate is expired.
 type LazyRefreshCache struct {
 	uri          InstanceURI
-	logger       debug.Logger
+	logger       debug.ContextLogger
 	key          *rsa.PrivateKey
 	r            refresher
 	mu           sync.Mutex
@@ -39,7 +39,7 @@ type LazyRefreshCache struct {
 // NewLazyRefreshCache initializes a new LazyRefreshCache.
 func NewLazyRefreshCache(
 	uri InstanceURI,
-	l debug.Logger,
+	l debug.ContextLogger,
 	client *alloydbadmin.AlloyDBAdminClient,
 	key *rsa.PrivateKey,
 	_ time.Duration,
@@ -72,30 +72,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.uri.String(),
 		)
 		return c.cached, nil
 	}
 
 	c.logger.Debugf(
+		ctx,
 		"[%v] Connection info refresh operation started",
 		c.uri.String(),
 	)
 	ci, err := c.r.performRefresh(ctx, c.uri, c.key)
 	if err != nil {
 		c.logger.Debugf(
+			ctx,
 			"[%v] Connection info refresh operation failed, err = %v",
 			c.uri.String(),
 			err,
 		)
 		return ConnectionInfo{}, err
 	}
 	c.logger.Debugf(
+		ctx,
 		"[%v] Connection info refresh operation complete",
 		c.uri.String(),
 	)
 	c.logger.Debugf(
+		ctx,
 		"[%v] Current certificate expiration = %v",
 		c.uri.String(),
 		ci.Expiration.UTC().Format(time.RFC3339),

internal/alloydb/static.go

@@ -78,15 +78,15 @@ func (s *staticData) UnmarshalJSON(data []byte) error {
 
 // StaticConnectionInfoCache provides connection info that is never refreshed.
 type StaticConnectionInfoCache struct {
-	logger debug.Logger
+	logger debug.ContextLogger
 	info   ConnectionInfo
 }
 
 // NewStaticConnectionInfoCache creates a connection info cache that will
 // always return the predefined connection info within the provided io.Reader
 func NewStaticConnectionInfoCache(
 	inst InstanceURI,
-	l debug.Logger,
+	l debug.ContextLogger,
 	r io.Reader,
 ) (*StaticConnectionInfoCache, error) {
 	data, err := io.ReadAll(r)

options.go

@@ -46,7 +46,7 @@ type dialerConfig struct {
 	tokenSource    oauth2.TokenSource
 	userAgents     []string
 	useIAMAuthN    bool
-	logger         debug.Logger
+	logger         debug.ContextLogger
 	lazyRefresh    bool
 
 	staticConnInfo io.Reader
@@ -170,9 +170,29 @@ 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 logger for reporting on internal
 // operations. By default the debug logger is disabled.
+// Prefer WithContextLogger.
 func WithDebugLogger(l debug.Logger) Option {
+	return func(d *dialerConfig) {
+		d.logger = &debugLoggerWithoutContext{l}
+	}
+}
+
+// WithContextLogger configures a debug lgoger for reporting on internal
+// operations. By default the debug logger is disabled.
+func WithContextLogger(l debug.ContextLogger) Option {
 	return func(d *dialerConfig) {
 		d.logger = l
 	}