sql: added logging support

flake.lock

@@ -2,11 +2,11 @@
   "nodes": {
     "nixpkgs": {
       "locked": {
-        "lastModified": 1722640603,
+        "lastModified": 1723019560,
-        "narHash": "sha256-TcXjLVNd3VeH1qKPH335Tc4RbFDbZQX+d7rqnDUoRaY=",
+        "narHash": "sha256-O/kxmybNecC3Efr6ITOdtCzFv90/B2Iiedavj5aRWt0=",
         "owner": "NixOS",
         "repo": "nixpkgs",
-        "rev": "81610abc161d4021b29199aa464d6a1a521e0cc9",
+        "rev": "f5129fb42b9c262318130a97b47516946da3e7d7",
         "type": "github"
       },
       "original": {

flake.nix

@@ -46,7 +46,6 @@
           protoc-gen-go
           protoc-gen-connect-go
           protoc-gen-validate
-          impl
           goverter
           bobgen-sqlite
           air

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

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=

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
 }

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)

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,
 }

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)
+}

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),