lg functions now show correct call depth (#374)

* lg functions now show correct call depth

* fixed call depth reversed sign

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

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
 			}
 

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)
 }

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")
+}