fix (cache): support for DB debug logging (#5087)

(cherry picked from commit a7fe48b8d827d1bf68ff8eea205428dd5faae381)

go.mod

@@ -81,7 +81,7 @@ require (
 	nhooyr.io/websocket v1.8.10
 )
 
-require github.com/hashicorp/go-dbw v0.1.4
+require github.com/hashicorp/go-dbw v0.1.5-0.20240909162114-6cee92b3da36
 
 require (
 	github.com/DATA-DOG/go-sqlmock v1.5.2

go.sum

@@ -201,8 +201,8 @@ github.com/hashicorp/go-bexpr v0.1.13 h1:HNwp7vZrMpRq8VZXj8VF90LbZpRjQQpim1oJF0D
 github.com/hashicorp/go-bexpr v0.1.13/go.mod h1:gN7hRKB3s7yT+YvTdnhZVLTENejvhlkZ8UE4YVBS+Q8=
 github.com/hashicorp/go-cleanhttp v0.5.2 h1:035FKYIWjmULyFRBKPs8TBQoi0x6d9G4xc9neXJWAZQ=
 github.com/hashicorp/go-cleanhttp v0.5.2/go.mod h1:kO/YDlP8L1346E6Sodw+PrpBSV4/SoxCXGY6BqNFT48=
-github.com/hashicorp/go-dbw v0.1.4 h1:FipsEg7UbWiB8hBQylTYWJobG6jVr0LNoRdo9IClGs4=
-github.com/hashicorp/go-dbw v0.1.4/go.mod h1:/YHbfK7mgG9k09aB74Imw3fEOwno0eTtlFTTYGZ7SFk=
+github.com/hashicorp/go-dbw v0.1.5-0.20240909162114-6cee92b3da36 h1:rPD+2QPhCLq8mKMx2FnIaqR5PTNT+LzhjfacYWuvFzY=
+github.com/hashicorp/go-dbw v0.1.5-0.20240909162114-6cee92b3da36/go.mod h1:/YHbfK7mgG9k09aB74Imw3fEOwno0eTtlFTTYGZ7SFk=
 github.com/hashicorp/go-hclog v1.6.3 h1:Qr2kF+eVWjTiYmU7Y31tYlP1h0q/X3Nl3tPGdaB11/k=
 github.com/hashicorp/go-hclog v1.6.3/go.mod h1:W4Qnvbt70Wk/zYJryRzDRU/4r0kIg0PVHBcfoyhpF5M=
 github.com/hashicorp/go-kms-wrapping/extras/kms/v2 v2.0.0-20231219183231-6bac757bb482 h1:1DqTnLaNk658AEenlF4PNGYd9b1hXE/+0jSOBIGOAms=

internal/clientcache/internal/daemon/server.go

@@ -229,7 +229,8 @@ func (s *CacheServer) Serve(ctx context.Context, cmd Commander, opt ...Option) e
 	var store *db.DB
 	store, err = openStore(ctx,
 		WithUrl(ctx, s.conf.DatabaseUrl),
-		WithLogger(ctx, s.logger))
+		WithLogger(ctx, s.logger),
+	)
 	if err != nil {
 		return errors.Wrap(ctx, err, op)
 	}
@@ -527,7 +528,14 @@ func openStore(ctx context.Context, opt ...Option) (*db.DB, error) {
 		dbOpts = append(dbOpts, cachedb.WithUrl(url))
 	}
 	if !util.IsNil(opts.withLogger) {
-		dbOpts = append(dbOpts, cachedb.WithGormFormatter(opts.withLogger))
+		opts.withLogger.Log(hclog.Debug, "Store GormFormatter", "LogLevel", opts.withLogger.GetLevel())
+		switch {
+		case opts.withLogger.IsDebug():
+			dbOpts = append(dbOpts, cachedb.WithGormFormatter(gormDebugLogger{Logger: opts.withLogger}))
+			dbOpts = append(dbOpts, cachedb.WithDebug(true))
+		default:
+			dbOpts = append(dbOpts, cachedb.WithGormFormatter(opts.withLogger))
+		}
 	}
 	store, err := cachedb.Open(ctx, dbOpts...)
 	if err != nil {
@@ -563,3 +571,17 @@ const (
 	dbFileName = "cache.db"
 	fkPragma   = "?_pragma=foreign_keys(1)"
 )
+
+type gormDebugLogger struct {
+	hclog.Logger
+}
+
+func (g gormDebugLogger) Printf(msg string, values ...any) {
+	b := new(strings.Builder)
+	fmt.Fprintf(b, msg, values...)
+	g.Debug(b.String())
+}
+
+func getGormLogger(log hclog.Logger) gormDebugLogger {
+	return gormDebugLogger{Logger: log}
+}

internal/clientcache/internal/daemon/server_test.go

@@ -5,12 +5,16 @@ package daemon
 
 import (
 	"context"
+	"strings"
+	"sync"
 	"testing"
 
 	"github.com/hashicorp/boundary/api"
 	"github.com/hashicorp/boundary/api/roles"
 	"github.com/hashicorp/boundary/internal/cmd/base"
 	"github.com/hashicorp/boundary/internal/daemon/controller"
+	"github.com/hashicorp/boundary/internal/db"
+	"github.com/hashicorp/go-hclog"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -19,10 +23,12 @@ func Test_openStore(t *testing.T) {
 	ctx := context.Background()
 	t.Run("success", func(t *testing.T) {
 		tmpDir := t.TempDir()
-		db, err := openStore(ctx, WithUrl(ctx, tmpDir+"/test.db"+fkPragma))
+		store, err := openStore(ctx, WithUrl(ctx, tmpDir+"/test.db"+fkPragma))
 		require.NoError(t, err)
-		require.NotNil(t, db)
+		require.NotNil(t, store)
 		assert.FileExists(t, tmpDir+"/test.db")
+		rw := db.New(store)
+		rw.Query(ctx, "select * from target", nil)
 	})
 	t.Run("homedir", func(t *testing.T) {
 		tmpDir := t.TempDir()
@@ -31,6 +37,32 @@ func Test_openStore(t *testing.T) {
 		require.NotNil(t, db)
 		assert.FileExists(t, tmpDir+"/"+dotDirname+"/"+dbFileName)
 	})
+	t.Run("log-level-debug", func(t *testing.T) {
+		buf := new(strings.Builder)
+		testLock := &sync.Mutex{}
+		testLogger := hclog.New(&hclog.LoggerOptions{
+			Mutex:      testLock,
+			Name:       "test",
+			JSONFormat: true,
+			Output:     buf,
+			Level:      hclog.Debug,
+		})
+		tmpDir := t.TempDir()
+		store, err := openStore(ctx,
+			WithUrl(ctx, tmpDir+"/test.db"+fkPragma),
+			WithLogger(ctx, testLogger),
+		)
+		require.NoError(t, err)
+		require.NotNil(t, store)
+		assert.FileExists(t, tmpDir+"/test.db")
+		rw := db.New(store)
+
+		rows, err := rw.Query(ctx, "select * from target", nil)
+		require.NoError(t, err)
+		defer rows.Close()
+		assert.Contains(t, buf.String(), "select * from target")
+		t.Log(buf.String())
+	})
 }
 
 // Note: the name of this test must remain short because the temp dir created

internal/clientcache/internal/db/db.go

@@ -54,8 +54,11 @@ func Open(ctx context.Context, opt ...Option) (*db.DB, error) {
 	if err != nil {
 		return nil, errors.Wrap(ctx, err, op)
 	}
-	conn.Debug(opts.withDebug)
-
+	defer func() {
+		// let's not capture the output of resetSchema and createTables, so
+		// we'll defer turning on debug
+		conn.Debug(opts.withDebug)
+	}()
 	switch {
 	case opts.withDbType == dbw.Sqlite && url == DefaultStoreUrl:
 		if err := createTables(ctx, conn); err != nil {