logs: update http and sql logs

cli/serve.go

@@ -20,7 +20,7 @@ var serveCmd = &cobra.Command{
 	Run: func(cmd *cobra.Command, args []string) {
 		db, err := db.Open(cfg)
 		if err != nil {
-			log.Log(cmd.Context()).Err(err).Error("failed to connect database")
+			log.New(cmd.Context()).Err(err).Error("failed to connect database")
 			os.Exit(1)
 		}
 
@@ -45,7 +45,7 @@ var serveCmd = &cobra.Command{
 		}()
 
 		if err := server.Start(exit); err != nil {
-			log.Log(cmd.Context()).Err(err).Error("failed to start server")
+			log.New(cmd.Context()).Err(err).Error("failed to start server")
 			os.Exit(1)
 		}
 	},

db/db.go

@@ -6,6 +6,7 @@ import (
 
 	_ "github.com/mattn/go-sqlite3"
 	"github.com/pressly/goose/v3"
+	sqldblogger "github.com/simukti/sqldb-logger"
 	"github.com/tigorlazuardi/redmage/config"
 	"github.com/tigorlazuardi/redmage/pkg/errs"
 )
@@ -14,7 +15,8 @@ var Migrations fs.FS
 
 func Open(cfg *config.Config) (*sql.DB, error) {
 	driver := cfg.String("db.driver")
-	db, err := sql.Open(driver, cfg.String("db.string"))
+	dsn := cfg.String("db.string")
+	db, err := sql.Open(driver, dsn)
 	if err != nil {
 		return db, errs.Wrapw(err, "failed to open database", "driver", driver)
 	}
@@ -32,5 +34,8 @@ func Open(cfg *config.Config) (*sql.DB, error) {
 		}
 	}
 
+	db = sqldblogger.OpenDriver(dsn, db.Driver(), sqlLogger{},
+		sqldblogger.WithSQLQueryAsMessage(true),
+	)
 	return db, err
 }

db/goose_logger.go

@@ -12,10 +12,10 @@ type gooseLogger struct{}
 
 func (gl *gooseLogger) Fatalf(format string, v ...interface{}) {
 	format = strings.TrimSuffix(format, "\n")
-	log.Log(context.Background()).Caller(caller.New(3)).Errorf(format, v...)
+	log.New(context.Background()).Caller(caller.New(3)).Errorf(format, v...)
 }
 
 func (gl *gooseLogger) Printf(format string, v ...interface{}) {
 	format = strings.TrimSuffix(format, "\n")
-	log.Log(context.Background()).Caller(caller.New(3)).Infof(format, v...)
+	log.New(context.Background()).Caller(caller.New(3)).Infof(format, v...)
 }

db/sql_logger.go

@@ -0,0 +1,29 @@
+package db
+
+import (
+	"context"
+	"log/slog"
+	"strings"
+
+	sqldblogger "github.com/simukti/sqldb-logger"
+	"github.com/tigorlazuardi/redmage/pkg/log"
+)
+
+type sqlLogger struct{}
+
+func (sqlLogger) Log(ctx context.Context, level sqldblogger.Level, msg string, data map[string]interface{}) {
+	var lvl slog.Level
+
+	msg = strings.TrimSpace(msg)
+
+	switch level {
+	case sqldblogger.LevelDebug, sqldblogger.LevelTrace:
+		lvl = slog.LevelDebug
+	case sqldblogger.LevelInfo:
+		lvl = slog.LevelInfo
+	case sqldblogger.LevelError:
+		lvl = slog.LevelError
+	}
+
+	log.New(ctx).With("sql", data).Level(lvl).Log(msg)
+}

go.mod

@@ -31,6 +31,7 @@ require (
 	github.com/mitchellh/copystructure v1.2.0 // indirect
 	github.com/mitchellh/reflectwalk v1.0.2 // indirect
 	github.com/sethvargo/go-retry v0.2.4 // indirect
+	github.com/simukti/sqldb-logger v0.0.0-20230108155151-646c1a075551 // indirect
 	go.uber.org/multierr v1.11.0 // indirect
 	golang.org/x/sync v0.6.0 // indirect
 	golang.org/x/sys v0.16.0 // indirect

go.sum

@@ -150,6 +150,8 @@ github.com/sethvargo/go-retry v0.2.4 h1:T+jHEQy/zKJf5s95UkguisicE0zuF9y7+/vgz08O
 github.com/sethvargo/go-retry v0.2.4/go.mod h1:1afjQuvh7s4gflMObvjLPaWgluLLyhA1wmVZ6KLpICw=
 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/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
 github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/spf13/cobra v1.8.0 h1:7aJaZx1B85qltLMc546zn58BxxfZdR/W22ej9CFoEf0=
@@ -208,6 +210,7 @@ google.golang.org/protobuf v1.31.0 h1:g0LDEJHgrBl9N9r17Ru3sqWhkIx2NB67okBHPwC7hs
 google.golang.org/protobuf v1.31.0/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqwMG9pJV4I=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
 gopkg.in/yaml.v2 v2.4.0 h1:D8xgwECY7CYvx+Y2n4sBz93Jn9JRvxdiyyo8CTfuKaY=
 gopkg.in/yaml.v2 v2.4.0/go.mod h1:RDklbk79AGWmwhnvt/jBztapEOGDOx6ZbXqjP6csGnQ=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

pkg/errs/errs.go

@@ -139,7 +139,7 @@ func (er *Err) GetDetails() []any {
 }
 
 func (er *Err) Log(ctx context.Context) Error {
-	log.Log(ctx).Caller(er.caller).Err(er).Error(er.message)
+	log.New(ctx).Caller(er.caller).Err(er).Error(er.message)
 	return er
 }
 

pkg/log/log.go

@@ -45,15 +45,17 @@ func NewHandler(cfg *config.Config) slog.Handler {
 }
 
 type Entry struct {
-	ctx     context.Context
+	ctx       context.Context
-	handler slog.Handler
+	handler   slog.Handler
-	caller  caller.Caller
+	caller    caller.Caller
-	time    time.Time
+	time      time.Time
-	err     error
+	err       error
+	level     slog.Level
+	withAttrs []slog.Attr
 }
 
-// Log prepares a new entry to write logs.
+// New prepares a new entry to write logs.
-func Log(ctx context.Context) *Entry {
+func New(ctx context.Context) *Entry {
 	h := FromContext(ctx)
 	if h == nil {
 		h = handler
@@ -71,6 +73,57 @@ func (entry *Entry) Err(err error) *Entry {
 	return entry
 }
 
+func (entry *Entry) Level(lvl slog.Level) *Entry {
+	entry.level = lvl
+	return entry
+}
+
+// With adds fields to top level of the log entry.
+func (entry *Entry) With(fields ...any) *Entry {
+	entry.withAttrs = append(entry.withAttrs, argsToAttrSlice(fields)...)
+	return entry
+}
+
+const badKey = "!BADKEY"
+
+func argsToAttrSlice(args []any) []slog.Attr {
+	var (
+		attr  slog.Attr
+		attrs []slog.Attr
+	)
+	for len(args) > 0 {
+		attr, args = argsToAttr(args)
+		attrs = append(attrs, attr)
+	}
+	return attrs
+}
+
+func argsToAttr(args []any) (slog.Attr, []any) {
+	switch x := args[0].(type) {
+	case string:
+		if len(args) == 1 {
+			return slog.String(badKey, x), nil
+		}
+		return slog.Any(x, args[1]), args[2:]
+
+	case slog.Attr:
+		return x, args[1:]
+
+	default:
+		return slog.Any(badKey, x), args[1:]
+	}
+}
+
+func (entry *Entry) Log(message string, fields ...any) {
+	record := slog.NewRecord(entry.time, entry.level, message, entry.getCaller().PC)
+	record.AddAttrs(entry.getExtra()...)
+	record.AddAttrs(slog.Group("details", fields...))
+	if entry.err != nil {
+		record.AddAttrs(slog.Any("error", entry.err))
+	}
+	_ = entry.handler.Handle(entry.ctx, record)
+}
+
 func (entry *Entry) Info(message string, fields ...any) {
 	record := slog.NewRecord(entry.time, slog.LevelInfo, message, entry.getCaller().PC)
 	record.AddAttrs(entry.getExtra()...)
@@ -159,11 +212,13 @@ func (entry *Entry) getCaller() caller.Caller {
 }
 
 func (entry *Entry) getExtra() []slog.Attr {
-	out := make([]slog.Attr, 0, 1)
+	out := make([]slog.Attr, 0, 4)
 	if reqid := middleware.GetReqID(entry.ctx); reqid != "" {
 		out = append(out, slog.String("request.id", reqid))
 	}
 
+	out = append(out, entry.withAttrs...)
+
 	return out
 }
 

server/routes/api/subreddits_list.go

@@ -19,6 +19,6 @@ func (api *API) ListSubreddits(rw http.ResponseWriter, r *http.Request) {
 	}
 
 	if err := json.NewEncoder(rw).Encode(subs); err != nil {
-		log.Log(r.Context()).Err(err).Error("failed to list subreddits")
+		log.New(r.Context()).Err(err).Error("failed to list subreddits")
 	}
 }

server/routes/middleware/logger.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"log/slog"
 	"net/http"
+	"strings"
 	"time"
 
 	chimiddleware "github.com/go-chi/chi/v5/middleware"
@@ -21,26 +22,30 @@ type ChiEntry struct {
 }
 
 func (ch *ChiEntry) Write(status int, bytes int, header http.Header, elapsed time.Duration, extra interface{}) {
-	message := fmt.Sprintf("%s %s %d %dms", ch.request.Method, ch.request.URL.Path, status, elapsed.Milliseconds())
+	elasedStr := formatDuration(elapsed)
+	message := fmt.Sprintf("%s %s %d %s", ch.request.Method, ch.request.URL.Path, status, elasedStr)
 
 	requestLog := slog.Attr{Key: "request", Value: ch.extractRequestLog()}
-	responseLog := slog.Group("response", "status", status, "header", header, "bytes", bytes)
+	responseLog := slog.Group("response", "status", status, "headers", flatHeader(header), "bytes", bytes)
-	roundtripLog := slog.String("roundtrip", fmt.Sprintf("%dms", elapsed.Milliseconds()))
+	roundtripLog := slog.String("elapsed", elasedStr)
 
+	group := slog.Group("http", requestLog, responseLog, roundtripLog)
 	if status >= 400 {
-		log.Log(ch.request.Context()).Error(message, requestLog, responseLog, roundtripLog)
+		log.New(ch.request.Context()).With(group).Error(message)
 		return
 	}
 
-	log.Log(ch.request.Context()).Info(message, requestLog, responseLog, roundtripLog)
+	log.New(ch.request.Context()).With(group).Info(message)
 }
 
 func (ch *ChiEntry) Panic(v interface{}, stack []byte) {
-	entry := log.Log(ch.request.Context())
+	group := slog.Group("http", slog.Attr{Key: "request", Value: ch.extractRequestLog()})
+	entry := log.New(ch.request.Context())
+	message := fmt.Sprintf("[PANIC] %s %s", ch.request.Method, ch.request.URL)
 	if err, ok := v.(error); ok {
-		entry.Err(err).Error("panic occurred", "stack", string(stack))
+		entry.Err(err).With(group).Error(message, "stack", string(stack))
 	} else {
-		entry.Error("panic occurred", "panic_data", v, "stack", string(stack))
+		entry.With(group).Error(message, "panic_data", v, "stack", string(stack))
 	}
 }
 
@@ -54,6 +59,21 @@ func (ch *ChiEntry) extractRequestLog() slog.Value {
 	if len(queries) > 0 {
 		values = append(values, slog.Any("query", queries))
 	}
-	values = append(values, slog.Any("headers", ch.request.Header))
+	values = append(values, slog.Any("headers", flatHeader(ch.request.Header)))
 	return slog.GroupValue(values...)
 }
+
+func flatHeader(header http.Header) map[string]string {
+	m := make(map[string]string, len(header))
+
+	for k := range header {
+		m[k] = strings.Join(header[k], "; ")
+	}
+	return m
+}
+
+func formatDuration(dur time.Duration) string {
+	nanosecs := float64(dur)
+
+	return fmt.Sprintf("%.3fms", nanosecs/float64(time.Millisecond))
+}

server/server.go

@@ -23,13 +23,13 @@ func (srv *Server) Start(exit <-chan struct{}) error {
 	errch := make(chan error, 1)
 	caller := caller.New(3)
 	go func() {
-		log.Log(context.Background()).Caller(caller).Info("starting http server", "address", "http://"+srv.server.Addr)
+		log.New(context.Background()).Caller(caller).Info("starting http server", "address", "http://"+srv.server.Addr)
 		errch <- srv.server.ListenAndServe()
 	}()
 
 	select {
 	case <-exit:
-		log.Log(context.Background()).Caller(caller).Info("received exit signal. shutting down server")
+		log.New(context.Background()).Caller(caller).Info("received exit signal. shutting down server")
 		ctx, cancel := context.WithTimeout(context.Background(), srv.config.Duration("http.shutdown_timeout"))
 		defer cancel()
 		return srv.server.Shutdown(ctx)