From a7fe48b8d827d1bf68ff8eea205428dd5faae381 Mon Sep 17 00:00:00 2001 From: Jim Date: Mon, 9 Sep 2024 12:38:18 -0400 Subject: [PATCH] fix (cache): support for DB debug logging (#5087) --- go.mod | 2 +- go.sum | 4 +-- .../clientcache/internal/daemon/server.go | 26 ++++++++++++-- .../internal/daemon/server_test.go | 36 +++++++++++++++++-- internal/clientcache/internal/db/db.go | 7 ++-- 5 files changed, 66 insertions(+), 9 deletions(-) diff --git a/go.mod b/go.mod index 5ea6dfd898..afd1f1e160 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 6af6fe0838..46ac09a092 100644 --- a/go.sum +++ b/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= diff --git a/internal/clientcache/internal/daemon/server.go b/internal/clientcache/internal/daemon/server.go index cd0f13e77c..cc642629b7 100644 --- a/internal/clientcache/internal/daemon/server.go +++ b/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} +} diff --git a/internal/clientcache/internal/daemon/server_test.go b/internal/clientcache/internal/daemon/server_test.go index 2f7e947c90..660f73dd3f 100644 --- a/internal/clientcache/internal/daemon/server_test.go +++ b/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 diff --git a/internal/clientcache/internal/db/db.go b/internal/clientcache/internal/db/db.go index 974faa7fbf..96443f533c 100644 --- a/internal/clientcache/internal/db/db.go +++ b/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 {