From 847f7c10cc796761e81a86e0551f00832a5056d5 Mon Sep 17 00:00:00 2001 From: Torkel Rogstad Date: Tue, 14 May 2024 18:32:39 +0200 Subject: [PATCH] feat: expose context to debug logger (#797) Co-authored-by: Eno Compton Co-authored-by: Jack Wotherspoon --- README.md | 6 ++--- debug/debug.go | 10 +++++++++ dialer.go | 35 +++++++++++++++--------------- internal/cloudsql/instance.go | 11 ++++++++-- internal/cloudsql/instance_test.go | 2 +- internal/cloudsql/lazy.go | 9 ++++++-- internal/cloudsql/refresh.go | 4 ++-- options.go | 23 +++++++++++++++++++- 8 files changed, 72 insertions(+), 28 deletions(-) diff --git a/README.md b/README.md index 48c67b5a..19e69d0f 100644 --- a/README.md +++ b/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... } diff --git a/debug/debug.go b/debug/debug.go index 962d9cfb..49017995 100644 --- a/debug/debug.go +++ b/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{}) +} diff --git a/dialer.go b/dialer.go index 0542f541..7f0bbbd1 100644 --- a/dialer.go +++ b/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,7 +362,7 @@ 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 @@ -370,12 +370,13 @@ func validClientCert(cn instance.ConnName, l debug.Logger, expiration time.Time) 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( diff --git a/internal/cloudsql/instance.go b/internal/cloudsql/instance.go index f32b3e8f..78620dec 100644 --- a/internal/cloudsql/instance.go +++ b/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), diff --git a/internal/cloudsql/instance_test.go b/internal/cloudsql/instance_test.go index 9b3f5f0b..ac239044 100644 --- a/internal/cloudsql/instance_test.go +++ b/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 { diff --git a/internal/cloudsql/lazy.go b/internal/cloudsql/lazy.go index 5ff3dfbf..5d62b022 100644 --- a/internal/cloudsql/lazy.go +++ b/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,6 +80,7 @@ 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(), ) @@ -87,12 +88,14 @@ func (c *LazyRefreshCache) ConnectionInfo( } 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, @@ -100,10 +103,12 @@ func (c *LazyRefreshCache) ConnectionInfo( 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), diff --git a/internal/cloudsql/refresh.go b/internal/cloudsql/refresh.go index a746bb70..c2056561 100644 --- a/internal/cloudsql/refresh.go +++ b/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 diff --git a/options.go b/options.go index 94695834..f59a3344 100644 --- a/options.go +++ b/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 }