Skip to content

Commit b94a5ff

Browse files
authored
feat: entryhuman: Log the caller's relative module path and function (#138)
* Update go.mod * Reset color before each line Some tools like modd (https://github.com/cortesi/modd) will try to color noncolored text but we don't want them to and so we reset at the beginning of each line to make sure they aren't playing with our output. * entryhuman: Log the caller's relative module path and function Instead of just their file's basename. * Fix tests
1 parent 8191438 commit b94a5ff

File tree

6 files changed

+78
-13
lines changed

6 files changed

+78
-13
lines changed

go.mod

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ require (
66
cloud.google.com/go v0.99.0
77
github.com/alecthomas/chroma v0.9.4
88
github.com/fatih/color v1.13.0
9+
github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da // indirect
910
github.com/google/go-cmp v0.5.6
1011
go.opencensus.io v0.23.0
1112
golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9

go.sum

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -83,8 +83,9 @@ github.com/go-gl/glfw/v3.3/glfw v0.0.0-20200222043503-6f7a984d4dc4/go.mod h1:tQ2
8383
github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q=
8484
github.com/golang/groupcache v0.0.0-20190702054246-869f871628b6/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
8585
github.com/golang/groupcache v0.0.0-20191227052852-215e87163ea7/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
86-
github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e h1:1r7pUrabqp18hOBcwBwiTsbnFeTZHV9eER/QT5JVZxY=
8786
github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
87+
github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da h1:oI5xCqsCo564l8iNU+DwB5epxmsaqB+rhGL0m5jtYqE=
88+
github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
8889
github.com/golang/mock v1.1.1/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
8990
github.com/golang/mock v1.2.0/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
9091
github.com/golang/mock v1.3.1/go.mod h1:sBzyDLLjw3U8JLTeZvSv8jJB+tU5PVekmnlKIyFUx0Y=

internal/entryhuman/entry.go

Lines changed: 66 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import (
99
"io"
1010
"os"
1111
"path/filepath"
12+
"runtime/debug"
1213
"strconv"
1314
"strings"
1415
"time"
@@ -50,7 +51,7 @@ func c(w io.Writer, attrs ...color.Attribute) *color.Color {
5051
// for extra lines in a log so if we did it here, the fields would be indented
5152
// twice in test logs. So the Stderr logger indents all the fields itself.
5253
func Fmt(w io.Writer, ent slog.SinkEntry) string {
53-
var ents string
54+
ents := c(w, color.Reset).Sprint("")
5455
ts := ent.Time.Format(TimeFormat)
5556
ents += ts + " "
5657

@@ -64,7 +65,8 @@ func Fmt(w io.Writer, ent slog.SinkEntry) string {
6465
ents += fmt.Sprintf("%v\t", loggerName)
6566
}
6667

67-
loc := fmt.Sprintf("<%v:%v>", filepath.Base(ent.File), ent.Line)
68+
hpath, hfn := humanPathAndFunc(ent.File, ent.Func)
69+
loc := fmt.Sprintf("<%v:%v>\t%v", hpath, ent.Line, hfn)
6870
loc = c(w, color.FgCyan).Sprint(loc)
6971
ents += fmt.Sprintf("%v\t", loc)
7072

@@ -127,7 +129,7 @@ func Fmt(w io.Writer, ent slog.SinkEntry) string {
127129
lines := strings.Split(multilineVal, "\n")
128130
for i, line := range lines[1:] {
129131
if line != "" {
130-
lines[i+1] = strings.Repeat(" ", len(multilineKey)+4) + line
132+
lines[i+1] = c(w, color.Reset).Sprint("") + strings.Repeat(" ", len(multilineKey)+4) + line
131133
}
132134
}
133135
multilineVal = strings.Join(lines, "\n")
@@ -194,3 +196,64 @@ func quoteKey(key string) string {
194196
// Replace spaces in the map keys with underscores.
195197
return strings.ReplaceAll(key, " ", "_")
196198
}
199+
200+
var mainPackagePath string
201+
var mainModulePath string
202+
203+
func init() {
204+
// Unfortunately does not work for tests yet :(
205+
// See https://github.com/golang/go/issues/33976
206+
bi, ok := debug.ReadBuildInfo()
207+
if !ok {
208+
return
209+
}
210+
mainPackagePath = bi.Path
211+
mainModulePath = bi.Main.Path
212+
}
213+
214+
// humanPathAndFunc takes the absolute path to a file and an absolute module path to a
215+
// function in that file and returns the module path to the file. It also returns
216+
// the path to the function stripped of its module prefix.
217+
//
218+
// If the file is in the main Go module then its path is returned
219+
// relative to the main Go module's root.
220+
//
221+
// fn is from https://pkg.go.dev/runtime#Func.Name
222+
func humanPathAndFunc(filename, fn string) (hpath, hfn string) {
223+
// pkgDir is the dir of the pkg.
224+
// e.g. cdr.dev/slog/internal
225+
// base is the package name and the function name separated by a period.
226+
// e.g. entryhuman.humanPathAndFunc
227+
// There can be multiple periods when methods of types are involved.
228+
pkgDir, base := filepath.Split(fn)
229+
s := strings.Split(base, ".")
230+
pkg := s[0]
231+
hfn = strings.Join(s[1:], ".")
232+
233+
if pkg == "main" {
234+
// This happens with go build main.go
235+
if mainPackagePath == "command-line-arguments" {
236+
// Without a real mainPath, we can't find the path to the file
237+
// relative to the module. So we just return the base.
238+
return filepath.Base(filename), hfn
239+
}
240+
// Go doesn't return the full main path in runtime.Func.Name()
241+
// It just returns the path "main"
242+
// Only runtime.ReadBuildInfo returns it so we have to check and replace.
243+
pkgDir = mainPackagePath
244+
// pkg main isn't reflected on the disk so we should not add it
245+
// into the pkgpath.
246+
pkg = ""
247+
}
248+
249+
hpath = filepath.Join(pkgDir, pkg, filepath.Base(filename))
250+
251+
if mainModulePath != "" {
252+
relhpath, err := filepath.Rel(mainModulePath, hpath)
253+
if err == nil {
254+
hpath = "./" + relhpath
255+
}
256+
}
257+
258+
return hpath, hfn
259+
}

internal/entryhuman/entry_test.go

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -32,8 +32,8 @@ func TestEntry(t *testing.T) {
3232

3333
File: "myfile",
3434
Line: 100,
35-
Func: "ignored",
36-
}, `2000-02-05 04:04:04.000 [DEBUG] <myfile:100> "wowowow\tizi"`)
35+
Func: "mypkg.ignored",
36+
}, `2000-02-05 04:04:04.000 [DEBUG] <mypkg/myfile:100> ignored "wowowow\tizi"`)
3737
})
3838

3939
t.Run("multilineMessage", func(t *testing.T) {
@@ -42,7 +42,7 @@ func TestEntry(t *testing.T) {
4242
test(t, slog.SinkEntry{
4343
Message: "line1\nline2",
4444
Level: slog.LevelInfo,
45-
}, `0001-01-01 00:00:00.000 [INFO] <.:0> ...
45+
}, `0001-01-01 00:00:00.000 [INFO] <.:0> ...
4646
"msg": line1
4747
line2`)
4848
})
@@ -54,7 +54,7 @@ func TestEntry(t *testing.T) {
5454
Message: "msg",
5555
Level: slog.LevelInfo,
5656
Fields: slog.M(slog.F("field", "line1\nline2")),
57-
}, `0001-01-01 00:00:00.000 [INFO] <.:0> msg ...
57+
}, `0001-01-01 00:00:00.000 [INFO] <.:0> msg ...
5858
"field": line1
5959
line2`)
6060
})
@@ -65,7 +65,7 @@ func TestEntry(t *testing.T) {
6565
test(t, slog.SinkEntry{
6666
Level: slog.LevelWarn,
6767
LoggerNames: []string{"named", "meow"},
68-
}, `0001-01-01 00:00:00.000 [WARN] (named.meow) <.:0> ""`)
68+
}, `0001-01-01 00:00:00.000 [WARN] (named.meow) <.:0> ""`)
6969
})
7070

7171
t.Run("trace", func(t *testing.T) {
@@ -77,7 +77,7 @@ func TestEntry(t *testing.T) {
7777
SpanID: trace.SpanID{0, 1, 2, 3, 4, 5, 6, 7},
7878
TraceID: trace.TraceID{0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15},
7979
},
80-
}, `0001-01-01 00:00:00.000 [ERROR] <.:0> "" {"trace": "000102030405060708090a0b0c0d0e0f", "span": "0001020304050607"}`)
80+
}, `0001-01-01 00:00:00.000 [ERROR] <.:0> "" {"trace": "000102030405060708090a0b0c0d0e0f", "span": "0001020304050607"}`)
8181
})
8282

8383
t.Run("color", func(t *testing.T) {
@@ -89,6 +89,6 @@ func TestEntry(t *testing.T) {
8989
slog.F("hey", "hi"),
9090
),
9191
})
92-
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)
92+
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)
9393
})
9494
}

s_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,5 +23,5 @@ func TestStdlib(t *testing.T) {
2323
et, rest, err := entryhuman.StripTimestamp(b.String())
2424
assert.Success(t, "strip timestamp", err)
2525
assert.False(t, "timestamp", et.IsZero())
26-
assert.Equal(t, "entry", " [INFO]\t(stdlib)\t<s_test.go:21>\tstdlib\t{\"hi\": \"we\"}\n", rest)
26+
assert.Equal(t, "entry", " [INFO]\t(stdlib)\t<cdr.dev/slog_test/s_test.go:21>\tTestStdlib\tstdlib\t{\"hi\": \"we\"}\n", rest)
2727
}

sloggers/sloghuman/sloghuman_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,5 +24,5 @@ func TestMake(t *testing.T) {
2424
et, rest, err := entryhuman.StripTimestamp(b.String())
2525
assert.Success(t, "strip timestamp", err)
2626
assert.False(t, "timestamp", et.IsZero())
27-
assert.Equal(t, "entry", " [INFO]\t<sloghuman_test.go:21>\t...\t{\"wowow\": \"me\\nyou\"}\n \"msg\": line1\n\n line2\n", rest)
27+
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)
2828
}

0 commit comments

Comments
 (0)