From 117d8765fcc2d1a2fc885d20dfc12e684b130ad0 Mon Sep 17 00:00:00 2001 From: Tigor Hutasuhut Date: Mon, 8 Apr 2024 15:48:45 +0700 Subject: [PATCH] logs: update http and sql logs --- cli/serve.go | 4 +- db/db.go | 7 ++- db/goose_logger.go | 4 +- db/sql_logger.go | 29 ++++++++++++ go.mod | 1 + go.sum | 3 ++ pkg/errs/errs.go | 2 +- pkg/log/log.go | 71 ++++++++++++++++++++++++---- server/routes/api/subreddits_list.go | 2 +- server/routes/middleware/logger.go | 38 +++++++++++---- server/server.go | 4 +- 11 files changed, 139 insertions(+), 26 deletions(-) create mode 100644 db/sql_logger.go diff --git a/cli/serve.go b/cli/serve.go index 7bc0a0d..9266b8f 100644 --- a/cli/serve.go +++ b/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) } }, diff --git a/db/db.go b/db/db.go index aafd882..2fdac5f 100644 --- a/db/db.go +++ b/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 } diff --git a/db/goose_logger.go b/db/goose_logger.go index 3b72939..0ced0de 100644 --- a/db/goose_logger.go +++ b/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...) } diff --git a/db/sql_logger.go b/db/sql_logger.go new file mode 100644 index 0000000..90d2fac --- /dev/null +++ b/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) +} diff --git a/go.mod b/go.mod index 6f1db7e..eb1ba14 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index c888023..764ecd0 100644 --- a/go.sum +++ b/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= diff --git a/pkg/errs/errs.go b/pkg/errs/errs.go index 2a5635d..5b91db7 100644 --- a/pkg/errs/errs.go +++ b/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 } diff --git a/pkg/log/log.go b/pkg/log/log.go index f785207..e61bb3c 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -45,15 +45,17 @@ func NewHandler(cfg *config.Config) slog.Handler { } type Entry struct { - ctx context.Context - handler slog.Handler - caller caller.Caller - time time.Time - err error + ctx context.Context + handler slog.Handler + caller caller.Caller + time time.Time + err error + level slog.Level + withAttrs []slog.Attr } -// Log prepares a new entry to write logs. -func Log(ctx context.Context) *Entry { +// New prepares a new entry to write logs. +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 } diff --git a/server/routes/api/subreddits_list.go b/server/routes/api/subreddits_list.go index e9c1603..2cac82e 100644 --- a/server/routes/api/subreddits_list.go +++ b/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") } } diff --git a/server/routes/middleware/logger.go b/server/routes/middleware/logger.go index f066007..2823209 100644 --- a/server/routes/middleware/logger.go +++ b/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) - roundtripLog := slog.String("roundtrip", fmt.Sprintf("%dms", elapsed.Milliseconds())) + responseLog := slog.Group("response", "status", status, "headers", flatHeader(header), "bytes", bytes) + 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)) +} diff --git a/server/server.go b/server/server.go index 9ab880f..c8691cf 100644 --- a/server/server.go +++ b/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)