diff --git a/internal/consts/logging.go b/internal/consts/logging.go deleted file mode 100644 index 622da8c..0000000 --- a/internal/consts/logging.go +++ /dev/null @@ -1,7 +0,0 @@ -package consts - -import "log/slog" - -const ( - LevelTrace slog.Level = slog.LevelDebug - 4 -) diff --git a/internal/domains/accounts/accounts.go b/internal/domains/accounts/accounts.go index 7458b84..01bf696 100644 --- a/internal/domains/accounts/accounts.go +++ b/internal/domains/accounts/accounts.go @@ -7,8 +7,8 @@ import ( "context" "errors" "fmt" - "log/slog" "ruben/inventory2/internal/consts" + "ruben/inventory2/internal/logging" "github.com/jackc/pgx/v5" "github.com/jackc/pgx/v5/pgxpool" @@ -16,7 +16,7 @@ import ( type ( Store struct { - log *slog.Logger + log *logging.Logger db *pgxpool.Pool } @@ -61,7 +61,7 @@ type ( } ) -func NewStore(logger *slog.Logger, db *pgxpool.Pool) *Store { +func NewStore(logger *logging.Logger, db *pgxpool.Pool) *Store { return &Store{ log: logger, db: db, diff --git a/internal/domains/authentication/auth.go b/internal/domains/authentication/auth.go index 646f6cd..098e869 100644 --- a/internal/domains/authentication/auth.go +++ b/internal/domains/authentication/auth.go @@ -5,7 +5,6 @@ import ( "encoding/json" "errors" "fmt" - "log/slog" "net/url" "time" @@ -16,6 +15,7 @@ import ( "golang.org/x/oauth2" "ruben/inventory2/internal/consts" + "ruben/inventory2/internal/logging" ) // TODO: move these to a config? @@ -37,7 +37,7 @@ const ( type ( // Authenticator is used to authenticate our users. Authenticator struct { - log *slog.Logger + log *logging.Logger *oidc.Provider oauth2.Config db *pgxpool.Pool @@ -64,7 +64,7 @@ type ( func New( ctx context.Context, db *pgxpool.Pool, - logger *slog.Logger, + logger *logging.Logger, ) (*Authenticator, error) { provider, err := oidc.NewProvider( ctx, diff --git a/internal/domains/platforms/etsy/etsy.go b/internal/domains/platforms/etsy/etsy.go index c786a91..f32adab 100644 --- a/internal/domains/platforms/etsy/etsy.go +++ b/internal/domains/platforms/etsy/etsy.go @@ -7,7 +7,6 @@ import ( "errors" "fmt" "io" - "log/slog" "net/http" "net/url" "strconv" @@ -18,6 +17,7 @@ import ( "github.com/jackc/pgx/v5/pgxpool" "ruben/inventory2/internal/domains/platforms/etsy/generated_client" + "ruben/inventory2/internal/logging" ) //go:generate oapi-codegen -generate types,client -package generated_client -o generated_client/client.go openapi.3.0.2.json @@ -33,7 +33,7 @@ import ( type ( Platform struct { - log *slog.Logger + log *logging.Logger oAuthRedirectURI func(acctID int64) string apiKeystring string apiSharedSecret string @@ -65,7 +65,7 @@ const ( scopeTransactionsWrite = "transactions_w" // Update a member's sales data. ) -func NewPlatform(logger *slog.Logger, oAuthRedirectURI func(acctID int64) string, apiKeystring, apiSharedSecret string, db *pgxpool.Pool) *Platform { +func NewPlatform(logger *logging.Logger, oAuthRedirectURI func(acctID int64) string, apiKeystring, apiSharedSecret string, db *pgxpool.Pool) *Platform { return &Platform{ log: logger, oAuthRedirectURI: oAuthRedirectURI, diff --git a/internal/domains/raw_events/events.go b/internal/domains/raw_events/events.go index fb8785b..9eee63b 100644 --- a/internal/domains/raw_events/events.go +++ b/internal/domains/raw_events/events.go @@ -4,7 +4,7 @@ import ( "context" "encoding/json" "fmt" - "log/slog" + "ruben/inventory2/internal/logging" "time" "github.com/jackc/pgx/v5" @@ -14,7 +14,7 @@ import ( type ( Store struct { - log *slog.Logger + log *logging.Logger db *pgxpool.Pool } @@ -27,7 +27,7 @@ type ( } ) -func NewStore(logger *slog.Logger, db *pgxpool.Pool) *Store { +func NewStore(logger *logging.Logger, db *pgxpool.Pool) *Store { return &Store{ log: logger, db: db, diff --git a/internal/logging/logger.go b/internal/logging/logger.go new file mode 100644 index 0000000..36f634d --- /dev/null +++ b/internal/logging/logger.go @@ -0,0 +1,180 @@ +package logging + +import ( + "context" + "fmt" + "log/slog" + "runtime" + "time" +) + +// Logger creates a *slog.Logger wrap with a few more methods wrapped on top. +// It recreates a number of methods to allow replacing a *slog.Logger functionally. +// It also implements a number of methods to support formatted messages and +// tracing. +type Logger struct { + *slog.Logger +} + +func New(h slog.Handler) *Logger { + return &Logger{ + Logger: slog.New(h), + } +} + +func From(l *slog.Logger) *Logger { + return &Logger{ + Logger: l, + } +} + +func (l *Logger) With(args ...any) *Logger { + return From(l.Logger.With(args...)) +} + +func (l *Logger) WithGroup(name string) *Logger { + return From(l.Logger.WithGroup(name)) +} + +func (l *Logger) Debugf(format string, args ...any) { + l.logContextf(context.Background(), slog.LevelDebug, format, args...) +} + +func (l *Logger) DebugContextf(ctx context.Context, format string, args ...any) { + l.logContextf(ctx, slog.LevelDebug, format, args...) +} + +func (l *Logger) DebugDeferf(format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(context.Background(), slog.LevelDebug, format, args...) +} + +func (l *Logger) DebugContextDeferf(ctx context.Context, format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(ctx, slog.LevelDebug, format, args...) +} + +func (l *Logger) DebugCallf(method string) func() { + return l.logContextCallf(context.Background(), slog.LevelDebug, method) +} + +func (l *Logger) DebugContextCallf(ctx context.Context, method string) func() { + return l.logContextCallf(ctx, slog.LevelDebug, method) +} + +func (l *Logger) Errorf(format string, args ...any) { + l.logContextf(context.Background(), slog.LevelError, format, args...) +} + +func (l *Logger) ErrorContextf(ctx context.Context, format string, args ...any) { + l.logContextf(ctx, slog.LevelError, format, args...) +} + +func (l *Logger) ErrorDeferf(format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(context.Background(), slog.LevelError, format, args...) +} + +func (l *Logger) ErrorContextDeferf(ctx context.Context, format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(ctx, slog.LevelError, format, args...) +} + +func (l *Logger) ErrorCallf(method string) func() { + return l.logContextCallf(context.Background(), slog.LevelError, method) +} + +func (l *Logger) ErrorContextCallf(ctx context.Context, method string) func() { + return l.logContextCallf(ctx, slog.LevelError, method) +} + +func (l *Logger) Infof(format string, args ...any) { + l.logContextf(context.Background(), slog.LevelInfo, format, args...) +} + +func (l *Logger) InfoContextf(ctx context.Context, format string, args ...any) { + l.logContextf(ctx, slog.LevelInfo, format, args...) +} + +func (l *Logger) InfoDeferf(format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(context.Background(), slog.LevelInfo, format, args...) +} + +func (l *Logger) InfoContextDeferf(ctx context.Context, format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(ctx, slog.LevelInfo, format, args...) +} + +func (l *Logger) InfoCallf(method string) func() { + return l.logContextCallf(context.Background(), slog.LevelInfo, method) +} + +func (l *Logger) InfoContextCallf(ctx context.Context, method string) func() { + return l.logContextCallf(ctx, slog.LevelInfo, method) +} + +func (l *Logger) Warnf(format string, args ...any) { + l.logContextf(context.Background(), slog.LevelWarn, format, args...) +} + +func (l *Logger) WarnContextf(ctx context.Context, format string, args ...any) { + l.logContextf(ctx, slog.LevelWarn, format, args...) +} + +func (l *Logger) WarnDeferf(format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(context.Background(), slog.LevelWarn, format, args...) +} + +func (l *Logger) WarnContextDeferf(ctx context.Context, format string, args ...any) func(func() (string, []any)) { + return l.logContextDeferf(ctx, slog.LevelWarn, format, args...) +} + +func (l *Logger) WarnCallf(method string) func() { + return l.logContextCallf(context.Background(), slog.LevelWarn, method) +} + +func (l *Logger) WarnContextCallf(ctx context.Context, method string) func() { + return l.logContextCallf(ctx, slog.LevelWarn, method) +} + +func (l *Logger) logContextf(ctx context.Context, lvl slog.Level, format string, args ...any) { + if !l.Enabled(ctx, slog.LevelInfo) { + return + } + + var pcs [1]uintptr + runtime.Callers(3, pcs[:]) // skip [Callers, Infof] + + _ = l.Handler().Handle( + ctx, + slog.NewRecord(time.Now(), lvl, fmt.Sprintf(format, args...), pcs[0]), + ) +} + +func (l *Logger) logContextCallf(ctx context.Context, lvl slog.Level, method string) func() { + fn := l.With("method", method).logContextDeferf(ctx, lvl, "%s called", method) + return func() { + fn(func() (string, []any) { + return "%s returned", []any{method} + }) + } +} + +func (l *Logger) logContextDeferf(ctx context.Context, lvl slog.Level, format string, args ...any) func(func() (msg string, args []any)) { + if !l.Enabled(ctx, slog.LevelInfo) { + return func(func() (string, []any)) { + } + } + + var pcs [1]uintptr + runtime.Callers(3, pcs[:]) // skip [Callers, Infof] + pc := pcs[0] + + _ = l.Handler().Handle(ctx, slog.NewRecord(time.Now(), lvl, fmt.Sprintf(format, args...), pc)) + return func(deferred func() (newFormat string, moreArgs []any)) { + if !l.Enabled(ctx, slog.LevelInfo) { + return + } + + if deferred != nil { + format, args = deferred() + } + + _ = l.Handler().Handle(ctx, slog.NewRecord(time.Now(), lvl, fmt.Sprintf(format, args...), pc)) + } +} diff --git a/internal/server/api/accounts/router.go b/internal/server/api/accounts/router.go index 7867054..f79bd88 100644 --- a/internal/server/api/accounts/router.go +++ b/internal/server/api/accounts/router.go @@ -3,10 +3,10 @@ package accounts import ( "errors" "fmt" - "log/slog" "net/http" "ruben/inventory2/internal/consts" "ruben/inventory2/internal/domains/accounts" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server/middleware" "ruben/inventory2/internal/server/response" "ruben/inventory2/internal/server/router" @@ -14,13 +14,13 @@ import ( ) type accountSubrouter struct { - log *slog.Logger + log *logging.Logger *router.SubMux accts *accounts.Store } func NewAccountSubrouter( - logger *slog.Logger, + logger *logging.Logger, accts *accounts.Store, authMiddleware *middleware.Auth, ) *accountSubrouter { diff --git a/internal/server/api/auth/router.go b/internal/server/api/auth/router.go index 8bf5546..d074e86 100644 --- a/internal/server/api/auth/router.go +++ b/internal/server/api/auth/router.go @@ -3,21 +3,21 @@ package auth import ( "context" "fmt" - "log/slog" "net/http" "ruben/inventory2/internal/domains/authentication" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server/cookies" "ruben/inventory2/internal/server/response" "ruben/inventory2/internal/server/router" ) type loginSubrouter struct { - log *slog.Logger + log *logging.Logger auth *authentication.Authenticator router.Subrouter } -func NewLoginSubrouter(logger *slog.Logger, auth *authentication.Authenticator) *loginSubrouter { +func NewLoginSubrouter(logger *logging.Logger, auth *authentication.Authenticator) *loginSubrouter { mux := router.NewSubMux(logger) ls := &loginSubrouter{ @@ -33,7 +33,7 @@ func NewLoginSubrouter(logger *slog.Logger, auth *authentication.Authenticator) return ls } -func (s *loginSubrouter) newLoginSubrouter(logger *slog.Logger) router.Subrouter { +func (s *loginSubrouter) newLoginSubrouter(logger *logging.Logger) router.Subrouter { mux := router.NewSubMux(logger) ls := &loginSubrouter{ diff --git a/internal/server/api/templates/router.go b/internal/server/api/templates/router.go index 5434210..503a0cf 100644 --- a/internal/server/api/templates/router.go +++ b/internal/server/api/templates/router.go @@ -3,7 +3,6 @@ package templates import ( "errors" "fmt" - "log/slog" "net/http" "net/url" "os" @@ -15,6 +14,7 @@ import ( "ruben/inventory2/internal/domains/accounts" etsy_platform "ruben/inventory2/internal/domains/platforms/etsy" "ruben/inventory2/internal/domains/raw_events" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server/middleware" "ruben/inventory2/internal/server/response" "ruben/inventory2/internal/server/router" @@ -23,7 +23,7 @@ import ( ) type webpageRouter struct { - log *slog.Logger + log *logging.Logger contentDir string templater *templater.Templater rawEvents *raw_events.Store @@ -33,7 +33,7 @@ type webpageRouter struct { } func NewWebpageRouter( - logger *slog.Logger, + logger *logging.Logger, contentDir string, tmpl *templater.Templater, rawEvents *raw_events.Store, @@ -66,8 +66,6 @@ func NewWebpageRouter( // compiles the page template or component template matching the url // func (s *Server) serveTemplates(r *http.Request) (response.Response, error) { func (s *webpageRouter) serveTemplates(r *http.Request) (response.Response, error) { - fmt.Println("webpageRouter.serveTemplates:", r.URL) - name, args := s.getTemplateNameAndArgs(r, s.contentDir+"/templates/component_bodies") b, err := s.templater.ExecuteComponentBody(name, args...) @@ -90,7 +88,6 @@ func (s *webpageRouter) serveTemplates(r *http.Request) (response.Response, erro // func (s *Server) getTemplateNameAndArgs(r *http.Request, templateDir string) (name string, args []any) { func (s *webpageRouter) getTemplateNameAndArgs(r *http.Request, templateDir string) (name string, args []any) { - fmt.Println("webpageRouter.getTemplateNameAndArgs:", r.URL) ctx := r.Context() name, pathParams := getTemplateNameForURL(r.URL, templateDir) diff --git a/internal/server/api/webhooks/etsy/webhooks.go b/internal/server/api/webhooks/etsy/webhooks.go index 1e45d89..95fc228 100644 --- a/internal/server/api/webhooks/etsy/webhooks.go +++ b/internal/server/api/webhooks/etsy/webhooks.go @@ -3,18 +3,18 @@ package etsy import ( "encoding/json" "fmt" - "log/slog" "net/http" "strconv" "time" "ruben/inventory2/internal/domains/platforms/etsy" "ruben/inventory2/internal/domains/raw_events" + "ruben/inventory2/internal/logging" ) type ( Webhooks struct { - log *slog.Logger + log *logging.Logger cfg Config db *raw_events.Store etsy *etsy.Platform @@ -26,7 +26,7 @@ type ( ) func NewWebhookHandler( - logger *slog.Logger, + logger *logging.Logger, db *raw_events.Store, platform *etsy.Platform, cfg Config, diff --git a/internal/server/api/webhooks/tiktok/webhooks.go b/internal/server/api/webhooks/tiktok/webhooks.go index 15535bb..69e0fe8 100644 --- a/internal/server/api/webhooks/tiktok/webhooks.go +++ b/internal/server/api/webhooks/tiktok/webhooks.go @@ -3,14 +3,14 @@ package tiktok import ( "encoding/json" "fmt" - "log/slog" "net/http" "time" "ruben/inventory2/internal/domains/raw_events" + "ruben/inventory2/internal/logging" ) -func NewWebhookHandler(logger *slog.Logger, db *raw_events.Store) http.Handler { +func NewWebhookHandler(logger *logging.Logger, db *raw_events.Store) http.Handler { mux := http.NewServeMux() mux.HandleFunc("POST /test", func(w http.ResponseWriter, r *http.Request) { diff --git a/internal/server/api/webhooks/webhooks.go b/internal/server/api/webhooks/webhooks.go index e45b06e..3eed72e 100644 --- a/internal/server/api/webhooks/webhooks.go +++ b/internal/server/api/webhooks/webhooks.go @@ -1,11 +1,11 @@ package webhooks import ( - "log/slog" "net/http" etsy_platform "ruben/inventory2/internal/domains/platforms/etsy" "ruben/inventory2/internal/domains/raw_events" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server/api/webhooks/etsy" "ruben/inventory2/internal/server/api/webhooks/tiktok" "ruben/inventory2/internal/server/api/webhooks/wix" @@ -16,7 +16,7 @@ type Config struct { } // TODO: just move over to the 'site' package, and then consider renaming the site package to something else? -func New(logger *slog.Logger, eventsDB *raw_events.Store, etsyPlatform *etsy_platform.Platform, cfg Config) http.Handler { +func New(logger *logging.Logger, eventsDB *raw_events.Store, etsyPlatform *etsy_platform.Platform, cfg Config) http.Handler { wh := http.NewServeMux() wh.Handle( diff --git a/internal/server/api/webhooks/wix/webhooks.go b/internal/server/api/webhooks/wix/webhooks.go index 85abccd..321d7a5 100644 --- a/internal/server/api/webhooks/wix/webhooks.go +++ b/internal/server/api/webhooks/wix/webhooks.go @@ -3,14 +3,14 @@ package wix import ( "encoding/json" "fmt" - "log/slog" "net/http" "time" "ruben/inventory2/internal/domains/raw_events" + "ruben/inventory2/internal/logging" ) -func NewWebhookHandler(logger *slog.Logger, db *raw_events.Store) http.Handler { +func NewWebhookHandler(logger *logging.Logger, db *raw_events.Store) http.Handler { mux := http.NewServeMux() mux.HandleFunc("POST /test", func(w http.ResponseWriter, r *http.Request) { diff --git a/internal/server/middleware/auth.go b/internal/server/middleware/auth.go index f5d15a8..8e6a7ef 100644 --- a/internal/server/middleware/auth.go +++ b/internal/server/middleware/auth.go @@ -6,20 +6,20 @@ import ( "errors" "fmt" "io" - "log/slog" "net/http" "time" "ruben/inventory2/internal/consts" "ruben/inventory2/internal/domains/accounts" "ruben/inventory2/internal/domains/authentication" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server/cookies" "ruben/inventory2/internal/server/response" ) type ( Auth struct { - log *slog.Logger + log *logging.Logger auth *authentication.Authenticator newLoginURL LoginURLProviderFunc accts *accounts.Store @@ -38,7 +38,7 @@ type ( ) func NewAuth( - logger *slog.Logger, + logger *logging.Logger, auth *authentication.Authenticator, newLoginURL LoginURLProviderFunc, accts *accounts.Store, diff --git a/internal/server/middleware/log.go b/internal/server/middleware/log.go index e60a2f5..f479329 100644 --- a/internal/server/middleware/log.go +++ b/internal/server/middleware/log.go @@ -2,14 +2,14 @@ package middleware import ( "context" - "log/slog" "net/http" "time" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server/response" ) -func LogRequests(ctx context.Context, logger *slog.Logger) response.Middleware { +func LogRequests(ctx context.Context, logger *logging.Logger) response.Middleware { reqIDCh := newRequestIDProvider(ctx) return func(fn response.HandlerFunc) response.HandlerFunc { diff --git a/internal/server/router/mux.go b/internal/server/router/mux.go index a65d3ed..dc2007e 100644 --- a/internal/server/router/mux.go +++ b/internal/server/router/mux.go @@ -2,13 +2,13 @@ package router import ( "fmt" - "log/slog" "net/http" "path" "slices" "strings" "ruben/inventory2/internal/consts" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server/response" ) @@ -16,7 +16,7 @@ type ( Mux struct { Mux *http.ServeMux middleware []response.Middleware - log *slog.Logger + log *logging.Logger } ) @@ -24,7 +24,7 @@ var ( ErrHandlerNotFound = fmt.Errorf("%w: handler not found", consts.ErrNotFound) ) -func NewMux(log *slog.Logger, ms ...response.Middleware) *Mux { +func NewMux(log *logging.Logger, ms ...response.Middleware) *Mux { return &Mux{ Mux: http.NewServeMux(), middleware: ms, @@ -37,12 +37,13 @@ func (m *Mux) AddMiddleware(ms ...response.Middleware) *Mux { return m } -func (m *Mux) traced(method, msg string, args ...any) func(func() (finalArgs []any)) { - return logTraceAndDefer(m.log, "Mux", method, msg, args...) -} - func (m *Mux) Handle(pattern string, fn response.HandlerFunc) { - defer m.traced("Handle", "", "pattern", pattern)(nil) + log := m.log.With( + "method", "Handle", + "patter", pattern, + "fn", fn, + ) + defer log.DebugCallf("called")() m.Mux.Handle(pattern, response.Handler(m.applyMiddleware(fn))) } @@ -59,7 +60,10 @@ func (m *Mux) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Route does not accept methods or ... wildcards // func (m *Mux) Route(basePathPattern string, sr Subrouter) { func (m *Mux) Route(pattern string, sr Subrouter) { - defer m.traced("Route", "pattern", pattern)(nil) + log := m.log.With("method", "Route", "pattern", pattern, "sr", sr) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", nil + }) // --- method, segments, _ := getHTTPMethodAndPathSegments(m.log, pattern) @@ -79,7 +83,7 @@ func (m *Mux) Route(pattern string, sr Subrouter) { if method != "" { cleanPattern = method + " " + cleanPattern } - logTrace(m.log, "mux", "Route", "cleanPattern: "+cleanPattern) + log.Debugf("cleanPattern: %s", cleanPattern) // --- /* @@ -123,11 +127,11 @@ type ( SubMux struct { tree *muxTree middleware []response.Middleware - log *slog.Logger + log *logging.Logger } ) -func NewSubMux(log *slog.Logger, ms ...response.Middleware) *SubMux { +func NewSubMux(log *logging.Logger, ms ...response.Middleware) *SubMux { return &SubMux{ tree: newMuxTree(log.WithGroup("muxTree")), middleware: ms, @@ -135,13 +139,9 @@ func NewSubMux(log *slog.Logger, ms ...response.Middleware) *SubMux { } } -func (m *SubMux) traced(method, msg string, args ...any) func(func() (finalArgs []any)) { - return logTraceAndDefer(m.log, "SubMux", method, msg, args...) -} - // TODO: this is capturing all subroutes! func (m *SubMux) Handle(pattern string, fn response.HandlerFunc) { - defer m.traced("Handle", "", "pattern", pattern)(nil) + defer m.log.With("pattern", pattern, "fn", fn).DebugCallf("Handle")() m.tree.set(pattern, m.applyMiddleware(fn)) } @@ -149,8 +149,8 @@ func (m *SubMux) Handle(pattern string, fn response.HandlerFunc) { // Route does not accept methods or ... wildcards // func (m *SubMux) Route(basePathPattern string, sr Subrouter) { func (m *SubMux) Route(pattern string, sr Subrouter) { - //defer m.traced("Route", "", "basePathPattern", basePathPattern)(nil) - defer m.traced("Route", "", "pattern", pattern)(nil) + log := m.log.With("method", "Route", "pattern", pattern, "sr", sr) + defer log.DebugCallf("Route")() method, segments, _ := getHTTPMethodAndPathSegments(m.log, pattern) if pattern == "" || (len(segments) == 0 && pattern[len(pattern)-1] != '/') { @@ -169,7 +169,7 @@ func (m *SubMux) Route(pattern string, sr Subrouter) { if method != "" { cleanPattern = method + " " + cleanPattern } - logTrace(m.log, "SubMux", "Route", "Handle about to be called", "cleanPattern", cleanPattern) + log.Debugf("Handle about to be called: cleanPattern: %s", cleanPattern) // --- /* @@ -238,11 +238,16 @@ func (m *SubMux) Route(pattern string, sr Subrouter) { // */ // } -func buildSubrouterHandlerFunc(logger *slog.Logger, numPatternSegments int, sr Subrouter) response.HandlerFunc { - defer logTraceAndDefer(logger, "", "buildSubrouterHandlerFunc", "", "numPatternSegments", numPatternSegments)(nil) +func buildSubrouterHandlerFunc(logger *logging.Logger, numPatternSegments int, sr Subrouter) response.HandlerFunc { + log := logger.With( + "function", "buildSubrouterHandlerFunc", + "numPatternSegments", numPatternSegments, + ) + return func(r *http.Request) (res response.Response, err error) { - defer logTraceAndDefer(logger, "", "buildSubrouterHandlerFunc", "", "numPatternSegments", numPatternSegments, "r.URL", r.URL)(func() []any { - return []any{ + log := log.With("r.URL", r.URL) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", []any{ "res", res, "err", err, } @@ -275,9 +280,9 @@ func buildSubrouterHandlerFunc(logger *slog.Logger, numPatternSegments int, sr S // do the request - logTrace(logger, "", "buildSubrouterHandlerFunc", "handler called", "subpath", r.URL.Path) + log.Debugf("handler called: %s", r.URL) fn, params, ok := sr.Handler(r) - logTrace(logger, "", "buildSubrouterHandlerFunc", "handler returned", "subpath", r.URL.Path, "fn", fn, "params", params, "ok", ok) + log.Debugf("handler returned: url = %s, fn = %v, params = %v, ok = %v", r.URL, fn, params, ok) if !ok { return nil, response.NotFound().Wrap(ErrHandlerNotFound) } @@ -293,8 +298,13 @@ func buildSubrouterHandlerFunc(logger *slog.Logger, numPatternSegments int, sr S } func (m *SubMux) Handler(r *http.Request) (fn response.HandlerFunc, params map[string]string, found bool) { - defer m.traced("Handler", "", "r.URL", r.URL)(func() []any { - return []any{ + log := m.log.With( + "method", "Handler", + "r.URL", r.URL, + ) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", []any{ + "fn", fn, "params", params, "found", found, } @@ -310,7 +320,7 @@ func (m *SubMux) applyMiddleware(fn response.HandlerFunc) response.HandlerFunc { type ( muxTree struct { - log *slog.Logger + log *logging.Logger branches map[string]*muxTree wildcardKey string @@ -322,17 +332,13 @@ type ( } ) -func newMuxTree(log *slog.Logger) *muxTree { +func newMuxTree(log *logging.Logger) *muxTree { return &muxTree{ log: log, branches: make(map[string]*muxTree), } } -func (m *muxTree) traced(method, msg string, args ...any) func(func() (finalArgs []any)) { - return logTraceAndDefer(m.log, "muxTree", method, msg, args...) -} - func (m *muxTree) String() string { if m == nil { return "" @@ -370,11 +376,12 @@ func (m *muxTree) String() string { } func (m *muxTree) set(pattern string, fn response.HandlerFunc) { - defer m.traced("set", "", "pattern", pattern)(func() []any { - return []any{ - "muxTree", m, - } - }) + log := m.log.With( + "method", "set", + "patter", pattern, + "fn", fn, + ) + defer log.DebugCallf("called")() method, segments, trailingSlash, endOfURLWildcard := getHTTPMethodAndPathSegmentsDroppingEndOfURLWildcard(m.log, pattern) m.setBySegments( method, @@ -387,18 +394,15 @@ func (m *muxTree) set(pattern string, fn response.HandlerFunc) { // TODO: handle /{$} properly func (m *muxTree) setBySegments(method string, segments []string, trailingSlash, endOfURLWildcard bool, fn response.HandlerFunc) { - defer m.traced( - "setBySegments", - "", - "method", method, + log := m.log.With( + "method", "setBySegments", + "arg.method", method, "segments", segments, "trailingSlash", trailingSlash, "endOfURLWildcard", endOfURLWildcard, - )(func() []any { - return []any{ - "muxTree", m, - } - }) + "fn", fn, + ) + defer log.DebugCallf("called")() if len(segments) == 0 { m.method = method if !trailingSlash || endOfURLWildcard { @@ -454,8 +458,13 @@ func (m *muxTree) setBySegments(method string, segments []string, trailingSlash, } func (m *muxTree) get(method, pattern string) (fn response.HandlerFunc, params map[string]string, found bool) { - defer m.traced("get", "", "method", method, "pattern", pattern)(func() []any { - return []any{ + log := m.log.With( + "method", "get", + "arg.method", method, + "pattern", pattern, + ) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", []any{ "fn", fn, "params", params, "found", found, @@ -466,15 +475,22 @@ func (m *muxTree) get(method, pattern string) (fn response.HandlerFunc, params m } func (m *muxTree) getByHTTPMethodAndSegments(method string, segments []string, trailingSlash bool) (fn response.HandlerFunc, params map[string]string, found bool) { - defer m.traced("getByHTTPMethodAndSegments", "", "method", method, "segments", segments, "trailingSlash", trailingSlash)(func() []any { - return []any{ + log := m.log.With( + "method", "getByHTTPMethodAndSegments", + "arg.method", method, + "segments", segments, + "trailingSlash", trailingSlash, + "muxTree", m, + ) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", []any{ "fn", fn, "params", params, "found", found, } }) if len(segments) == 0 { - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "no segments", "tree", m) + log.Debugf("no segments") if methodMatches := m.method == "" || m.method == method; methodMatches { if fn = m.handler; fn == nil { fn = m.subrouteHandler @@ -497,42 +513,50 @@ func (m *muxTree) getByHTTPMethodAndSegments(method string, segments []string, t } if sm, ok := m.branches[head]; ok { - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "matching branch found", "head", head, "sm", sm) + log.Debugf("matching branch found") //return sm.getByHTTPMethodAndSegments(method, tail, trailingSlash) if fn, params, found = sm.getByHTTPMethodAndSegments(method, tail, trailingSlash); found { return fn, params, found } - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "matching branch mismatched at subpath") + log.Debugf("matching branch mismatched at subpath") } else { - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "no matching branch found") + log.Debugf("no matching branch found") } if sm := m.wildcardBranch; sm != nil { - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "wildcard branch found", "m.wildcardKey", m.wildcardKey, "sm", sm) + wlog := log.With( + "wildcardKey", m.wildcardKey, + "sub.muxTree", sm, + ) + wlog.Debugf("wildcard branch found") //fn, params, found = sm.getByHTTPMethodAndSegments(method, tail, trailingSlash) if fn, params, found = sm.getByHTTPMethodAndSegments(method, tail, trailingSlash); found { params[m.wildcardKey] = head return fn, params, found } - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "wildcard branch mismatched at subpath") + wlog.Debugf("wildcard branch mismatched at subpath") } else { - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "no wildcard branch found") + log.Debugf("no wildcard branch found") } // --- TODO: test --- if m.subrouteHandler != nil && (m.method == method || m.method == "") { - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "subroutes captured", "m", m) + log.Debugf("subroutes captured") return m.subrouteHandler, nil, true } - logTrace(m.log, "muxTree", "getByHTTPMethodAndSegments", "subroutes not captured", "m", m) + log.Debugf("subroutes not captured") // --- return nil, map[string]string{}, false } -func getHTTPMethodAndPathSegmentsDroppingEndOfURLWildcard(logger *slog.Logger, pattern string) (method string, segments []string, trailingSlash, endOfURLWildcard bool) { - defer logTraceAndDefer(logger, "", "getHTTPMethodAndPathSegmentsDroppingEndOfURLWildcard", "", "pattern", pattern)(func() []any { - return []any{ +func getHTTPMethodAndPathSegmentsDroppingEndOfURLWildcard(logger *logging.Logger, pattern string) (method string, segments []string, trailingSlash, endOfURLWildcard bool) { + log := logger.With( + "function", "getHTTPMethodAndPathSegmentsDroppingEndOfURLWildcard", + "pattern", pattern, + ) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", []any{ "method", method, "segments", segments, "trailingSlash", trailingSlash, @@ -548,9 +572,13 @@ func getHTTPMethodAndPathSegmentsDroppingEndOfURLWildcard(logger *slog.Logger, p return method, segments, trailingSlash, endOfURLWildcard } -func getHTTPMethodAndPathSegments(logger *slog.Logger, pattern string) (method string, segments []string, trailingSlash bool) { - defer logTraceAndDefer(logger, "", "getHTTPMethodAndPathSegments", "", "pattern", pattern)(func() []any { - return []any{ +func getHTTPMethodAndPathSegments(logger *logging.Logger, pattern string) (method string, segments []string, trailingSlash bool) { + log := logger.With( + "function", "getHTTPMethodAndPathSegments", + "pattern", pattern, + ) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", []any{ "method", method, "segments", segments, "trailingSlash", trailingSlash, @@ -565,13 +593,12 @@ func getHTTPMethodAndPathSegments(logger *slog.Logger, pattern string) (method s return method, segments, trailingSlash } -func getPathSegments(logger *slog.Logger, pathPattern string) (segments []string, trailingSlash bool) { - defer logTraceAndDefer(logger, "", "getPathSegments", "", "pathPattern", pathPattern)(func() []any { - return []any{ - "segments", segments, - "trailingSlash", trailingSlash, - } - }) +func getPathSegments(logger *logging.Logger, pathPattern string) (segments []string, trailingSlash bool) { + log := logger.With( + "function", "getPathSegments", + "pathPattern", pathPattern, + ) + defer log.DebugCallf("getPathSegments")() trailingSlash = strings.HasSuffix(pathPattern, "/") p := strings.Trim(path.Clean(pathPattern), "/") @@ -583,9 +610,13 @@ func getPathSegments(logger *slog.Logger, pathPattern string) (segments []string } // NOTE: if endOfURLWildcard, then trailingSlash -func getPathSegmentsWithoutEndOfURLWildcard(logger *slog.Logger, pathPattern string) (segments []string, trailingSlash, endOfURLWildcard bool) { - defer logTraceAndDefer(logger, "", "getPathSegmentsWithoutEndOfURLWildcard", "", "pathPattern", pathPattern)(func() []any { - return []any{ +func getPathSegmentsWithoutEndOfURLWildcard(logger *logging.Logger, pathPattern string) (segments []string, trailingSlash, endOfURLWildcard bool) { + log := logger.With( + "function", "getPathSegmentsWithoutEndOfURLWildcard", + "pathPattern", pathPattern, + ) + defer log.DebugDeferf("called")(func() (string, []any) { + return "returned", []any{ "segments", segments, "trailingSlash", trailingSlash, "endOfURLWildcard", endOfURLWildcard, @@ -625,33 +656,4 @@ func applyMiddleware(fn response.HandlerFunc, ms ...response.Middleware) respons return fn } -// logging utilities - -func logTraceAndDefer(logger *slog.Logger, typeName, method, msg string, args ...any) func(func() (finalArgs []any)) { - fmsg := fmt.Sprintf("%s.%s called", typeName, method) - if msg != "" { - fmsg = fmt.Sprintf("%s: %s", fmsg, msg) - } - - logger.Log(nil, consts.LevelTrace, fmsg, args...) - return func(cb func() (finalArgs []any)) { - if cb != nil { - args = append(args, cb()...) - } - fmsg := fmt.Sprintf("%s.%s returned", typeName, method) - if msg != "" { - fmsg = fmt.Sprintf("%s: %s", fmsg, msg) - } - - logger.Log(nil, consts.LevelTrace, fmsg, args...) - } -} - -func logTrace(logger *slog.Logger, typeName, method, msg string, args ...any) { - fmsg := fmt.Sprintf("%s.%s", typeName, method) - if msg != "" { - fmsg = fmt.Sprintf("%s: %s", fmsg, msg) - } - - logger.Log(nil, consts.LevelTrace, fmsg, args...) -} +// TODO: remove the consts. trace level diff --git a/internal/server/server.go b/internal/server/server.go index 0bd5281..0c55808 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -6,7 +6,6 @@ import ( "errors" "fmt" "html/template" - "log/slog" "net/http" "path" "strconv" @@ -17,6 +16,7 @@ import ( "ruben/inventory2/internal/domains/authentication" etsy_platform "ruben/inventory2/internal/domains/platforms/etsy" "ruben/inventory2/internal/domains/raw_events" + "ruben/inventory2/internal/logging" accounts_api "ruben/inventory2/internal/server/api/accounts" auth_api "ruben/inventory2/internal/server/api/auth" templates_api "ruben/inventory2/internal/server/api/templates" @@ -29,7 +29,7 @@ import ( func NewServer( ctx context.Context, - logger *slog.Logger, + logger *logging.Logger, contentDir string, rawEvents *raw_events.Store, accts *accounts.Store, diff --git a/main.go b/main.go index ff8ff10..b3076ef 100644 --- a/main.go +++ b/main.go @@ -24,6 +24,7 @@ import ( "ruben/inventory2/internal/domains/authentication" etsy_platform "ruben/inventory2/internal/domains/platforms/etsy" "ruben/inventory2/internal/domains/raw_events" + "ruben/inventory2/internal/logging" "ruben/inventory2/internal/server" ) @@ -33,10 +34,9 @@ const ( ) func main() { - logger := slog.New(tint.NewHandler(os.Stderr, &tint.Options{ + logger := logging.New(tint.NewHandler(os.Stderr, &tint.Options{ AddSource: true, Level: slog.LevelDebug, - //Level: consts.LevelTrace, ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { // this can perform general key=value log cleanup @@ -50,6 +50,24 @@ func main() { // Time format (Default: time.StampMilli) //TimeFormat: "", })) + /* + logger := slog.New(tint.NewHandler(os.Stderr, &tint.Options{ + AddSource: true, + Level: slog.LevelDebug, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + // this can perform general key=value log cleanup + + if a.Key == slog.SourceKey && len(groups) == 0 { + source := a.Value.Any().(*slog.Source) + source.File = strings.TrimPrefix(source.File, "/home/angel/go/src/ruben/inventory2/internal") + } + + return a + }, + // Time format (Default: time.StampMilli) + //TimeFormat: "", + })) + */ logger.Info("application starting") @@ -60,7 +78,7 @@ func main() { logger.Info("application shutdown") } -func runApp(ctx context.Context, logger *slog.Logger) error { +func runApp(ctx context.Context, logger *logging.Logger) error { ctx, shutdown := context.WithCancel(ctx) defer shutdown() @@ -149,7 +167,7 @@ func runAuthProcesses(ctx context.Context, auth *authentication.Authenticator) < return errCh } -func runServer(ctx context.Context, logger *slog.Logger, connPool *pgxpool.Pool, auth *authentication.Authenticator) <-chan error { +func runServer(ctx context.Context, logger *logging.Logger, connPool *pgxpool.Pool, auth *authentication.Authenticator) <-chan error { srv := &http.Server{ Addr: ":8082", // local Handler: server.NewServer(