feat: entryhuman: Log the caller's relative module path and function

go.mod

@@ -6,6 +6,7 @@ require (
 	cloud.google.com/go v0.99.0
 	github.com/alecthomas/chroma v0.9.4
 	github.com/fatih/color v1.13.0
+	github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da // indirect
 	github.com/google/go-cmp v0.5.6
 	go.opencensus.io v0.23.0
 	golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9

go.sum

@@ -83,8 +83,9 @@ github.com/go-gl/glfw/v3.3/glfw v0.0.0-20200222043503-6f7a984d4dc4/go.mod h1:tQ2
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q=
 github.com/golang/groupcache v0.0.0-20190702054246-869f871628b6/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
 github.com/golang/groupcache v0.0.0-20191227052852-215e87163ea7/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
-github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e h1:1r7pUrabqp18hOBcwBwiTsbnFeTZHV9eER/QT5JVZxY=
 github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
+github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da h1:oI5xCqsCo564l8iNU+DwB5epxmsaqB+rhGL0m5jtYqE=
+github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
 github.com/golang/mock v1.1.1/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
 github.com/golang/mock v1.2.0/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
 github.com/golang/mock v1.3.1/go.mod h1:sBzyDLLjw3U8JLTeZvSv8jJB+tU5PVekmnlKIyFUx0Y=

internal/entryhuman/entry.go

@@ -9,6 +9,7 @@ import (
 	"io"
 	"os"
 	"path/filepath"
+	"runtime/debug"
 	"strconv"
 	"strings"
 	"time"
@@ -50,7 +51,7 @@ func c(w io.Writer, attrs ...color.Attribute) *color.Color {
 // for extra lines in a log so if we did it here, the fields would be indented
 // twice in test logs. So the Stderr logger indents all the fields itself.
 func Fmt(w io.Writer, ent slog.SinkEntry) string {
-	var ents string
+	ents := c(w, color.Reset).Sprint("")
 	ts := ent.Time.Format(TimeFormat)
 	ents += ts + " "
 
@@ -64,7 +65,8 @@ func Fmt(w io.Writer, ent slog.SinkEntry) string {
 		ents += fmt.Sprintf("%v\t", loggerName)
 	}
 
-	loc := fmt.Sprintf("<%v:%v>", filepath.Base(ent.File), ent.Line)
+	hpath, hfn := humanPathAndFunc(ent.File, ent.Func)
+	loc := fmt.Sprintf("<%v:%v>\t%v", hpath, ent.Line, hfn)
 	loc = c(w, color.FgCyan).Sprint(loc)
 	ents += fmt.Sprintf("%v\t", loc)
 
@@ -127,7 +129,7 @@ func Fmt(w io.Writer, ent slog.SinkEntry) string {
 		lines := strings.Split(multilineVal, "\n")
 		for i, line := range lines[1:] {
 			if line != "" {
-				lines[i+1] = strings.Repeat(" ", len(multilineKey)+4) + line
+				lines[i+1] = c(w, color.Reset).Sprint("") + strings.Repeat(" ", len(multilineKey)+4) + line
 			}
 		}
 		multilineVal = strings.Join(lines, "\n")
@@ -194,3 +196,64 @@ func quoteKey(key string) string {
 	// Replace spaces in the map keys with underscores.
 	return strings.ReplaceAll(key, " ", "_")
 }
+
+var mainPackagePath string
+var mainModulePath string
+
+func init() {
+	// Unfortunately does not work for tests yet :(
+	// See https://github.com/golang/go/issues/33976
+	bi, ok := debug.ReadBuildInfo()
+	if !ok {
+		return
+	}
+	mainPackagePath = bi.Path
+	mainModulePath = bi.Main.Path
+}
+
+// humanPathAndFunc takes the absolute path to a file and an absolute module path to a
+// function in that file and returns the module path to the file. It also returns
+// the path to the function stripped of its module prefix.
+//
+// If the file is in the main Go module then its path is returned
+// relative to the main Go module's root.
+//
+// fn is from https://pkg.go.dev/runtime#Func.Name
+func humanPathAndFunc(filename, fn string) (hpath, hfn string) {
+	// pkgDir is the dir of the pkg.
+	//   e.g. cdr.dev/slog/internal
+	// base is the package name and the function name separated by a period.
+	//   e.g. entryhuman.humanPathAndFunc
+	// There can be multiple periods when methods of types are involved.
+	pkgDir, base := filepath.Split(fn)
+	s := strings.Split(base, ".")
+	pkg := s[0]
+	hfn = strings.Join(s[1:], ".")
+
+	if pkg == "main" {
+		// This happens with go build main.go
+		if mainPackagePath == "command-line-arguments" {
+			// Without a real mainPath, we can't find the path to the file
+			// relative to the module. So we just return the base.
+			return filepath.Base(filename), hfn
+		}
+		// Go doesn't return the full main path in runtime.Func.Name()
+		// It just returns the path "main"
+		// Only runtime.ReadBuildInfo returns it so we have to check and replace.
+		pkgDir = mainPackagePath
+		// pkg main isn't reflected on the disk so we should not add it
+		// into the pkgpath.
+		pkg = ""
+	}
+
+	hpath = filepath.Join(pkgDir, pkg, filepath.Base(filename))
+
+	if mainModulePath != "" {
+		relhpath, err := filepath.Rel(mainModulePath, hpath)
+		if err == nil {
+			hpath = "./" + relhpath
+		}
+	}
+
+	return hpath, hfn
+}

internal/entryhuman/entry_test.go

@@ -32,8 +32,8 @@ func TestEntry(t *testing.T) {
 
 			File: "myfile",
 			Line: 100,
-			Func: "ignored",
-		}, `2000-02-05 04:04:04.000 [DEBUG]	<myfile:100>	"wowowow\tizi"`)
+			Func: "mypkg.ignored",
+		}, `2000-02-05 04:04:04.000 [DEBUG]	<mypkg/myfile:100>	ignored	"wowowow\tizi"`)
 	})
 
 	t.Run("multilineMessage", func(t *testing.T) {
@@ -42,7 +42,7 @@ func TestEntry(t *testing.T) {
 		test(t, slog.SinkEntry{
 			Message: "line1\nline2",
 			Level:   slog.LevelInfo,
-		}, `0001-01-01 00:00:00.000 [INFO]	<.:0>	...
+		}, `0001-01-01 00:00:00.000 [INFO]	<.:0>		...
 "msg": line1
        line2`)
 	})
@@ -54,7 +54,7 @@ func TestEntry(t *testing.T) {
 			Message: "msg",
 			Level:   slog.LevelInfo,
 			Fields:  slog.M(slog.F("field", "line1\nline2")),
-		}, `0001-01-01 00:00:00.000 [INFO]	<.:0>	msg ...
+		}, `0001-01-01 00:00:00.000 [INFO]	<.:0>		msg ...
 "field": line1
          line2`)
 	})
@@ -65,7 +65,7 @@ func TestEntry(t *testing.T) {
 		test(t, slog.SinkEntry{
 			Level:       slog.LevelWarn,
 			LoggerNames: []string{"named", "meow"},
-		}, `0001-01-01 00:00:00.000 [WARN]	(named.meow)	<.:0>	""`)
+		}, `0001-01-01 00:00:00.000 [WARN]	(named.meow)	<.:0>		""`)
 	})
 
 	t.Run("trace", func(t *testing.T) {
@@ -77,7 +77,7 @@ func TestEntry(t *testing.T) {
 				SpanID:  trace.SpanID{0, 1, 2, 3, 4, 5, 6, 7},
 				TraceID: trace.TraceID{0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15},
 			},
-		}, `0001-01-01 00:00:00.000 [ERROR]	<.:0>	""	{"trace": "000102030405060708090a0b0c0d0e0f", "span": "0001020304050607"}`)
+		}, `0001-01-01 00:00:00.000 [ERROR]	<.:0>		""	{"trace": "000102030405060708090a0b0c0d0e0f", "span": "0001020304050607"}`)
 	})
 
 	t.Run("color", func(t *testing.T) {
@@ -89,6 +89,6 @@ func TestEntry(t *testing.T) {
 				slog.F("hey", "hi"),
 			),
 		})
-		assert.Equal(t, "entry", "0001-01-01 00:00:00.000 \x1b[91m[CRITICAL]\x1b[0m\t\x1b[36m<.:0>\x1b[0m\t\"\"\t{\x1b[34m\"hey\"\x1b[0m: \x1b[32m\"hi\"\x1b[0m}", act)
+		assert.Equal(t, "entry", "\x1b[0m\x1b[0m0001-01-01 00:00:00.000 \x1b[91m[CRITICAL]\x1b[0m\t\x1b[36m<.:0>	\x1b[0m\t\"\"\t{\x1b[34m\"hey\"\x1b[0m: \x1b[32m\"hi\"\x1b[0m}", act)
 	})
 }

s_test.go

@@ -23,5 +23,5 @@ func TestStdlib(t *testing.T) {
 	et, rest, err := entryhuman.StripTimestamp(b.String())
 	assert.Success(t, "strip timestamp", err)
 	assert.False(t, "timestamp", et.IsZero())
-	assert.Equal(t, "entry", " [INFO]\t(stdlib)\t<s_test.go:21>\tstdlib\t{\"hi\": \"we\"}\n", rest)
+	assert.Equal(t, "entry", " [INFO]\t(stdlib)\t<cdr.dev/slog_test/s_test.go:21>\tTestStdlib\tstdlib\t{\"hi\": \"we\"}\n", rest)
 }

sloggers/sloghuman/sloghuman_test.go

@@ -24,5 +24,5 @@ func TestMake(t *testing.T) {
 	et, rest, err := entryhuman.StripTimestamp(b.String())
 	assert.Success(t, "strip timestamp", err)
 	assert.False(t, "timestamp", et.IsZero())
-	assert.Equal(t, "entry", " [INFO]\t<sloghuman_test.go:21>\t...\t{\"wowow\": \"me\\nyou\"}\n  \"msg\": line1\n\n         line2\n", rest)
+	assert.Equal(t, "entry", " [INFO]\t<cdr.dev/slog/sloggers/sloghuman_test/sloghuman_test.go:21>\tTestMake\t...\t{\"wowow\": \"me\\nyou\"}\n  \"msg\": line1\n\n         line2\n", rest)
 }