From 19a058dc11211a0a1e144f869d3a65c37f854f17 Mon Sep 17 00:00:00 2001 From: Tigor Hutasuhut Date: Thu, 8 Aug 2024 13:41:18 +0700 Subject: [PATCH] sql: added logging support --- flake.lock | 6 ++--- flake.nix | 1 - go.mod | 1 + go.sum | 2 ++ go/api/devices_create.go | 4 ++- go/api/devices_get_by_slug.go | 7 ++++- go/cmd/bluemage/serve/serve.go | 15 ++++++++--- go/pkg/log/sql.go | 48 ++++++++++++++++++++++++++++++++++ go/server/interceptor.go | 4 +-- 9 files changed, 77 insertions(+), 11 deletions(-) create mode 100644 go/pkg/log/sql.go diff --git a/flake.lock b/flake.lock index 3ef4b7b..5196c8c 100644 --- a/flake.lock +++ b/flake.lock @@ -2,11 +2,11 @@ "nodes": { "nixpkgs": { "locked": { - "lastModified": 1722640603, - "narHash": "sha256-TcXjLVNd3VeH1qKPH335Tc4RbFDbZQX+d7rqnDUoRaY=", + "lastModified": 1723019560, + "narHash": "sha256-O/kxmybNecC3Efr6ITOdtCzFv90/B2Iiedavj5aRWt0=", "owner": "NixOS", "repo": "nixpkgs", - "rev": "81610abc161d4021b29199aa464d6a1a521e0cc9", + "rev": "f5129fb42b9c262318130a97b47516946da3e7d7", "type": "github" }, "original": { diff --git a/flake.nix b/flake.nix index 771288e..ddded7a 100644 --- a/flake.nix +++ b/flake.nix @@ -46,7 +46,6 @@ protoc-gen-go protoc-gen-connect-go protoc-gen-validate - impl goverter bobgen-sqlite air diff --git a/go.mod b/go.mod index 82d6c4a..c917828 100644 --- a/go.mod +++ b/go.mod @@ -28,6 +28,7 @@ require ( github.com/mattn/go-colorable v0.1.13 // indirect github.com/mattn/go-isatty v0.0.20 // indirect github.com/qdm12/reprint v0.0.0-20200326205758-722754a53494 // indirect + github.com/simukti/sqldb-logger v0.0.0-20230108155151-646c1a075551 // indirect github.com/spf13/pflag v1.0.5 // indirect github.com/stephenafamo/scan v0.4.2 // indirect github.com/stoewer/go-strcase v1.3.0 // indirect diff --git a/go.sum b/go.sum index 79b42cf..f3a5e3e 100644 --- a/go.sum +++ b/go.sum @@ -80,6 +80,8 @@ github.com/rs/cors v1.11.0/go.mod h1:XyqrcTp5zjWr1wsJ8PIRZssZ8b/WMcMf71DJnit4EMU github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM= github.com/shopspring/decimal v1.3.1 h1:2Usl1nmF/WZucqkFZhnfFYxxxu8LG21F6nPQBE5gKV8= github.com/shopspring/decimal v1.3.1/go.mod h1:DKyhrW/HYNuLGql+MJL6WCR6knT2jwCFRcu2hWCYk4o= +github.com/simukti/sqldb-logger v0.0.0-20230108155151-646c1a075551 h1:+EXKKt7RC4HyE/iE8zSeFL+7YBL8Z7vpBaEE3c7lCnk= +github.com/simukti/sqldb-logger v0.0.0-20230108155151-646c1a075551/go.mod h1:ztTX0ctjRZ1wn9OXrzhonvNmv43yjFUXJYJR95JQAJE= github.com/spf13/cast v1.5.0 h1:rj3WzYc11XZaIZMPKmwP96zkFEnnAmV8s6XbB2aY32w= github.com/spf13/cast v1.5.0/go.mod h1:SpXXQ5YoyJw6s3/6cMTQuxvgRl3PCJiyaX9p6b155UU= github.com/spf13/cobra v1.8.1 h1:e5/vxKd/rZsfSJMUX1agtjeTDf+qv1/JdBF8gg5k9ZM= diff --git a/go/api/devices_create.go b/go/api/devices_create.go index 2e873b0..7776603 100644 --- a/go/api/devices_create.go +++ b/go/api/devices_create.go @@ -10,9 +10,11 @@ import ( "github.com/mattn/go-sqlite3" "github.com/tigorlazuardi/bluemage/go/gen/models" "github.com/tigorlazuardi/bluemage/go/pkg/errs" + "github.com/tigorlazuardi/bluemage/go/pkg/log" ) func (api *API) DevicesCreate(ctx context.Context, params *models.Device) (device *models.Device, err error) { + ctx, coll := log.WithQueryCollector(ctx) now := time.Now() api.lockf(func() { device, err = models.Devices.Insert(ctx, api.DB, &models.DeviceSetter{ @@ -40,7 +42,7 @@ func (api *API) DevicesCreate(ctx context.Context, params *models.Device) (devic Code(connect.CodeAlreadyExists) } } - return nil, errs.Wrapw(err, "failed to create device", "params", params) + return nil, errs.Wrapw(err, "failed to create device", "params", params, "query", coll) } return device, nil } diff --git a/go/api/devices_get_by_slug.go b/go/api/devices_get_by_slug.go index 8b11410..b958e63 100644 --- a/go/api/devices_get_by_slug.go +++ b/go/api/devices_get_by_slug.go @@ -6,13 +6,18 @@ import ( "connectrpc.com/connect" "github.com/tigorlazuardi/bluemage/go/gen/models" "github.com/tigorlazuardi/bluemage/go/pkg/errs" + "github.com/tigorlazuardi/bluemage/go/pkg/log" ) func (api *API) GetDevice(ctx context.Context, slug string) (device *models.Device, err error) { + ctx, coll := log.WithQueryCollector(ctx) device, err = models.FindDevice(ctx, api.DB, slug) if err != nil { if err.Error() == "sql: no rows in result set" { - return device, errs.Wrapw(err, "device not found", "slug", slug).Code(connect.CodeNotFound) + return device, errs.Wrapw(err, "device not found", + "slug", slug, + "query", coll, + ).Code(connect.CodeNotFound) } return device, errs.Wrapw(err, "failed to find device", "slug", slug) diff --git a/go/cmd/bluemage/serve/serve.go b/go/cmd/bluemage/serve/serve.go index def6e72..b23a8d9 100644 --- a/go/cmd/bluemage/serve/serve.go +++ b/go/cmd/bluemage/serve/serve.go @@ -2,6 +2,7 @@ package serve import ( "context" + "database/sql" "errors" "log/slog" "net/http" @@ -9,6 +10,7 @@ import ( "time" "connectrpc.com/connect" + sqldblogger "github.com/simukti/sqldb-logger" "github.com/spf13/cobra" "github.com/stephenafamo/bob" "github.com/tigorlazuardi/bluemage/go/api" @@ -23,11 +25,18 @@ import ( var Cmd = &cobra.Command{ Use: "serve", RunE: func(cmd *cobra.Command, args []string) error { - db, err := bob.Open("sqlite3", "file:data.db") + sqldb, err := sql.Open("sqlite3", "file:data.db") if err != nil { - return errs.Wrap(err, "failed to open database") + return errs.Wrapw(err, "failed to open database", "file", "data.db") } + sqldb = sqldblogger.OpenDriver( + "file:data.db", + sqldb.Driver(), + log.SQLLogger{}, + sqldblogger.WithSQLQueryAsMessage(true), + ) + db := bob.New(sqldb) logOutput := log.WrapOsFile(os.Stderr) prettyHandler := log.NewPrettyHandler(logOutput, nil) slog.SetDefault(slog.New(prettyHandler)) @@ -63,7 +72,7 @@ var Cmd = &cobra.Command{ if err != nil && !errors.Is(err, http.ErrServerClosed) { return errs.Wrap(err, "failed to serve") } - return errors.Join(db.Close()) + return errors.Join(sqldb.Close()) }, SilenceUsage: true, } diff --git a/go/pkg/log/sql.go b/go/pkg/log/sql.go new file mode 100644 index 0000000..5dbdc92 --- /dev/null +++ b/go/pkg/log/sql.go @@ -0,0 +1,48 @@ +package log + +import ( + "context" + "log/slog" + "strings" + + sqldblogger "github.com/simukti/sqldb-logger" +) + +var _ sqldblogger.Logger = (*SQLLogger)(nil) + +type SQLLogger struct{} + +var _ slog.LogValuer = (*QueryCollector)(nil) + +type QueryCollector struct { + Statement string + Args any +} + +func (qu *QueryCollector) LogValue() slog.Value { + return slog.GroupValue( + slog.String("statement", strings.ReplaceAll(qu.Statement, `"`, "")), + slog.Any("args", qu.Args), + ) +} + +type queryCollectorKey struct{} + +func QueryCollectorFromContext(ctx context.Context) *QueryCollector { + coll, _ := ctx.Value(queryCollectorKey{}).(*QueryCollector) + return coll +} + +func WithQueryCollector(ctx context.Context) (context.Context, *QueryCollector) { + coll := &QueryCollector{} + return context.WithValue(ctx, queryCollectorKey{}, coll), coll +} + +func (SQLLogger) Log(ctx context.Context, level sqldblogger.Level, msg string, data map[string]interface{}) { + if qc := QueryCollectorFromContext(ctx); qc != nil { + qc.Statement = msg + qc.Args = data["args"] + return + } + slog.ErrorContext(ctx, strings.ReplaceAll(msg, "\n", " "), "lvl", level.String(), "data", data) +} diff --git a/go/server/interceptor.go b/go/server/interceptor.go index 4c738fb..7f5c997 100644 --- a/go/server/interceptor.go +++ b/go/server/interceptor.go @@ -18,14 +18,14 @@ func LogInterceptor() connect.UnaryInterceptorFunc { dur := time.Since(start) durFloat := float64(dur) / float64(time.Second) if err != nil { - slog.Error("RPC Error", + slog.ErrorContext(ctx, "RPC Error", "procedure", ar.Spec().Procedure, "method", ar.HTTPMethod(), "duration", fmt.Sprintf("%.3fs", durFloat), "error", errs.DrillToError(err), ) } else { - slog.Info("RPC Call", + slog.InfoContext(ctx, "RPC Call", "procedure", ar.Spec().Procedure, "method", ar.HTTPMethod(), "duration", fmt.Sprintf("%.3fs", durFloat),