From f8704d0385390656d0245884f6a3730b1a596cad Mon Sep 17 00:00:00 2001 From: Neil O'Toole Date: Sat, 27 Jan 2024 08:12:02 -0700 Subject: [PATCH] lg functions now show correct call depth (#374) * lg functions now show correct call depth * fixed call depth reversed sign --- cli/cmd_version.go | 4 +-- libsq/core/ioz/lockfile/lockfile.go | 5 +-- libsq/core/lg/lg.go | 42 ++++++++++++++--------- libsq/core/lg/lg_test.go | 52 +++++++++++++++++++++++++++++ 4 files changed, 82 insertions(+), 21 deletions(-) diff --git a/cli/cmd_version.go b/cli/cmd_version.go index e037a1b9..2cfb9ca9 100644 --- a/cli/cmd_version.go +++ b/cli/cmd_version.go @@ -89,9 +89,7 @@ func execVersion(cmd *cobra.Command, _ []string) error { go func() { var err error v, err := fetchBrewVersion(ctx) - if err != nil { - lg.Error(logFrom(cmd), "Get brew version", err) - } + lg.WarnIfError(logFrom(cmd), "Get brew version", err) // OK if v is empty resultCh <- v diff --git a/libsq/core/ioz/lockfile/lockfile.go b/libsq/core/ioz/lockfile/lockfile.go index 8f5e14ab..681c1024 100644 --- a/libsq/core/ioz/lockfile/lockfile.go +++ b/libsq/core/ioz/lockfile/lockfile.go @@ -4,6 +4,7 @@ package lockfile import ( "context" "errors" + "log/slog" "path/filepath" "time" @@ -45,7 +46,7 @@ func (l Lockfile) Lock(ctx context.Context, timeout time.Duration) error { log.Warn("Failed to acquire pid lock", lga.Path, string(l), lga.Err, err) return errz.Wrapf(err, "failed to acquire pid lock: %s", l) } - log.Debug("Acquired pid lock") + lg.Depth(log, slog.LevelDebug, 1, "Acquired pid lock") return nil } @@ -56,7 +57,7 @@ func (l Lockfile) Lock(ctx context.Context, timeout time.Duration) error { err := lockfile.Lockfile(l).TryLock() attempts++ if err == nil { - log.Debug("Acquired pid lock", lga.Attempts, attempts) + lg.Depth(log, slog.LevelDebug, 6, "Acquired pid lock") return nil } diff --git a/libsq/core/lg/lg.go b/libsq/core/lg/lg.go index fc4459b2..aa44e98c 100644 --- a/libsq/core/lg/lg.go +++ b/libsq/core/lg/lg.go @@ -9,6 +9,8 @@ import ( "context" "io" "log/slog" + "runtime" + "time" "github.com/neilotoole/sq/libsq/core/lg/lga" "github.com/neilotoole/sq/libsq/core/lg/lgm" @@ -82,7 +84,7 @@ func WarnIfError(log *slog.Logger, msg string, err error) { msg = "Error" } - log.Warn(msg, lga.Err, err) + Depth(log, slog.LevelWarn, 1, msg, lga.Err, err) } // WarnIfFuncError executes fn (if non-nil), and logs a warning @@ -101,7 +103,7 @@ func WarnIfFuncError(log *slog.Logger, msg string, fn func() error) { msg = "Func error" } - log.Warn(msg, lga.Err, err) + Depth(log, slog.LevelWarn, 1, msg, lga.Err, err) } // WarnIfCloseError executes c.Close if is non-nil, and logs a warning @@ -120,19 +122,7 @@ func WarnIfCloseError(log *slog.Logger, msg string, c io.Closer) { msg = "Close error" } - log.Warn(msg, lga.Err, err) -} - -// Error logs an error if err is non-nil. -func Error(log *slog.Logger, msg string, err error, args ...any) { - if err == nil { - return - } - - a := []any{lga.Err, err} - a = append(a, args...) - - log.Error(msg, a...) + Depth(log, slog.LevelWarn, 1, msg, lga.Err, err) } // Unexpected is a convenience function for logging unexpected errors @@ -142,5 +132,25 @@ func Unexpected(log *slog.Logger, err error) { return } - log.Error(lgm.Unexpected, lga.Err, err) + Depth(log, slog.LevelError, 1, lgm.Unexpected, lga.Err, err) +} + +// Depth logs a message with the given call (pc skip) depth. +// This is useful for logging inside a helper function. +func Depth(log *slog.Logger, level slog.Level, depth int, msg string, args ...any) { + h := log.Handler() + ctx := context.Background() + + if !h.Enabled(ctx, level) { + return + } + + var pc uintptr + var pcs [1]uintptr + runtime.Callers(2+depth, pcs[:]) + pc = pcs[0] + + r := slog.NewRecord(time.Now(), level, msg, pc) + r.Add(args...) + _ = h.Handle(ctx, r) } diff --git a/libsq/core/lg/lg_test.go b/libsq/core/lg/lg_test.go index 03b4dd56..78787755 100644 --- a/libsq/core/lg/lg_test.go +++ b/libsq/core/lg/lg_test.go @@ -2,6 +2,9 @@ package lg_test import ( "context" + "errors" + "io" + "log/slog" "testing" "github.com/neilotoole/sq/libsq/core/lg" @@ -17,3 +20,52 @@ func TestContext(t *testing.T) { log.Info("huzzah") } + +func TestSourceAttr(t *testing.T) { + log := lgt.New(t) + log = log.With("name", "alice", "age", 42) + err := errors.New("TestSourceAttr error") + + log.Warn("TestSourceAttr - NO DEPTH") + lg.Depth(log, slog.LevelWarn, 0, "TestSourceAttr log depth") + lg.WarnIfError(log, "TestSourceAttr", err) + lg.WarnIfFuncError(log, "TestSourceAttr", errorFunc) + lg.WarnIfCloseError(log, "TestSourceAttr", errorCloser{}) + lg.Unexpected(log, err) + + nest1(log) +} + +func nest1(log *slog.Logger) { + err := errors.New("nest1 error") + log.Warn("nest1 - NO DEPTH") + lg.Depth(log, slog.LevelWarn, 0, "nest1 log depth") + lg.WarnIfError(log, "nest1", err) + lg.WarnIfFuncError(log, "nest1", errorFunc) + lg.WarnIfCloseError(log, "nest1", errorCloser{}) + lg.Unexpected(log, err) + + nest2(log) +} + +func nest2(log *slog.Logger) { + err := errors.New("nest2 error") + log.Warn("nest2 - NO DEPTH") + lg.Depth(log, slog.LevelWarn, 0, "nest2 log depth") + lg.WarnIfError(log, "nest2", err) + lg.WarnIfFuncError(log, "nest2", errorFunc) + lg.WarnIfCloseError(log, "nest2", errorCloser{}) + lg.Unexpected(log, err) +} + +func errorFunc() error { + return errors.New("errorFunc went bad") +} + +var _ io.Closer = errorCloser{} + +type errorCloser struct{} + +func (e errorCloser) Close() error { + return errors.New("errorCloser.Close went bad") +}