internal logging library

2026-01-12 23:21:52 -07:00
parent ee2808f8a1
commit 851234d9fa
18 changed files with 349 additions and 159 deletions
@@ -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 "<nil>"
@@ -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