From ffbea2a6aa4edaeb80c952ebab4bed0cb529c84d Mon Sep 17 00:00:00 2001 From: Ayman Bagabas Date: Tue, 21 Mar 2023 12:17:41 -0400 Subject: [PATCH] feat(logger): implement slog.Handler This implements slog.Handler interface. You can use Log as an slog handler. --- go.mod | 1 + go.sum | 33 +++++++++++++ json_test.go | 2 +- level.go | 24 +++++++++- logger.go | 124 +++++++++++++++++++++++++++++++++++++----------- options_test.go | 10 ++-- pkg.go | 1 - pkg_test.go | 14 +++--- text.go | 39 ++++++++++----- text_test.go | 2 +- 10 files changed, 196 insertions(+), 54 deletions(-) diff --git a/go.mod b/go.mod index ab3241d..1bf2b41 100644 --- a/go.mod +++ b/go.mod @@ -7,6 +7,7 @@ require ( github.com/go-logfmt/logfmt v0.6.0 github.com/mattn/go-isatty v0.0.17 github.com/stretchr/testify v1.8.2 + golang.org/x/exp v0.0.0-20230315142452-642cacee5cc0 ) require ( diff --git a/go.sum b/go.sum index b05c6b2..2a0d427 100644 --- a/go.sum +++ b/go.sum @@ -7,6 +7,7 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/go-logfmt/logfmt v0.6.0 h1:wGYYu3uicYdqXVgoYbvnkrPVXkuLM1p1ifugDMEdRi4= github.com/go-logfmt/logfmt v0.6.0/go.mod h1:WYhtIu8zTZfxdn5+rREduYbwxfcBr/Vr6KEVveWlfTs= +github.com/google/go-cmp v0.5.8/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/lucasb-eyer/go-colorful v1.2.0 h1:1nnpGOrhyZZuNyfu1QjKiUICQ74+3FNCN69Aj6K7nkY= github.com/lucasb-eyer/go-colorful v1.2.0/go.mod h1:R4dSotOR9KMtayYi1e77YzuveK+i7ruzyGqttikkLy0= github.com/mattn/go-isatty v0.0.17 h1:BTarxUcIeDqL27Mc+vyvdWYSL28zpIhv3RoTdsLMPng= @@ -30,9 +31,41 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/ github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= github.com/stretchr/testify v1.8.2 h1:+h33VjcLVPDHtOdpUCuF+7gSuG3yGIftsP1YvFihtJ8= github.com/stretchr/testify v1.8.2/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4= +github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY= +golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= +golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc= +golang.org/x/crypto v0.1.0/go.mod h1:RecgLatLF4+eUMCP1PoPZQb+cVrJcOPbHkTkbkB9sbw= +golang.org/x/exp v0.0.0-20230315142452-642cacee5cc0 h1:pVgRXcIictcr+lBQIFeiwuwtDIs4eL21OuM9nyAADmo= +golang.org/x/exp v0.0.0-20230315142452-642cacee5cc0/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc= +golang.org/x/mod v0.6.0-dev.0.20220419223038-86c51ed26bb4/go.mod h1:jJ57K6gSWd91VN4djpZkiMVwK6gcyfeH4XE8wZrZaV4= +golang.org/x/mod v0.6.0/go.mod h1:4mET923SAdbXp2ki8ey+zGs1SLqsuM2Y0uvdZR/fUNI= +golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= +golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg= +golang.org/x/net v0.0.0-20220722155237-a158d28d115b/go.mod h1:XRhObCWvk6IyKnWLug+ECip1KBveYUHfp+8e9klMJ9c= +golang.org/x/net v0.1.0/go.mod h1:Cx3nUiGt4eDBEyega/BKRp+/AlGL8hYe7U9odMt2Cco= +golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sync v0.0.0-20220722155255-886fb9371eb4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0 h1:MVltZSvRTcU2ljQOhs94SXPftV6DCNnZViHeQps87pQ= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= +golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= +golang.org/x/term v0.1.0/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= +golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= +golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= +golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ= +golang.org/x/text v0.4.0/go.mod h1:mrYo+phRRbMaCq/xk9113O4dZlRixOauAjOtrjsXDZ8= +golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= +golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/tools v0.1.12/go.mod h1:hNGJHUnrk76NpqgfD5Aqm5Crs+Hm0VOH/i9J2+nxYbc= +golang.org/x/tools v0.2.0/go.mod h1:y4OqIKeOV/fWJetJ8bXPU1sEVniLMIyDAZWeHdV+NTA= +golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/json_test.go b/json_test.go index a5a52b3..4234a89 100644 --- a/json_test.go +++ b/json_test.go @@ -177,5 +177,5 @@ func TestJsonCustomKey(t *testing.T) { logger.SetFormatter(JSONFormatter) logger.SetReportTimestamp(true) logger.Info("info") - require.Equal(t, "{\"lvl\":\"info\",\"msg\":\"info\",\"time\":\"0001/01/01 00:00:00\"}\n", buf.String()) + require.Equal(t, "{\"lvl\":\"info\",\"msg\":\"info\",\"time\":\"0002/01/01 00:00:00\"}\n", buf.String()) } diff --git a/level.go b/level.go index ae07909..f74127a 100644 --- a/level.go +++ b/level.go @@ -1,6 +1,10 @@ package log -import "strings" +import ( + "strings" + + "golang.org/x/exp/slog" +) // Level is a logging level. type Level int32 @@ -55,3 +59,21 @@ func ParseLevel(level string) Level { return InfoLevel } } + +// fromSlogLevel converts slog.Level to log.Level. +var fromSlogLevel = map[slog.Level]Level{ + slog.LevelDebug: DebugLevel, + slog.LevelInfo: InfoLevel, + slog.LevelWarn: WarnLevel, + slog.LevelError: ErrorLevel, + slog.Level(12): FatalLevel, +} + +// toSlogLevel converts log.Level to slog.Level. +var toSlogLevel = map[Level]slog.Level{ + DebugLevel: slog.LevelDebug, + InfoLevel: slog.LevelInfo, + WarnLevel: slog.LevelWarn, + ErrorLevel: slog.LevelError, + FatalLevel: slog.Level(12), +} diff --git a/logger.go b/logger.go index 7930982..d56276c 100644 --- a/logger.go +++ b/logger.go @@ -2,16 +2,20 @@ package log import ( "bytes" + "context" "fmt" "io" "io/ioutil" + "log" "os" "runtime" "strings" "sync" "sync/atomic" + "time" "github.com/charmbracelet/lipgloss" + "golang.org/x/exp/slog" ) var ( @@ -47,6 +51,52 @@ type Logger struct { helpers *sync.Map } +// Enabled reports whether the logger is enabled for the given level. +// +// Implements slog.Handler. +func (l *Logger) Enabled(_ context.Context, level slog.Level) bool { + return atomic.LoadInt32(&l.level) <= int32(fromSlogLevel[level]) +} + +// Handle handles the Record. It will only be called if Enabled returns true. +// +// Implements slog.Handler. +func (l *Logger) Handle(_ context.Context, record slog.Record) error { + fields := make([]interface{}, 0, record.NumAttrs()*2) + record.Attrs(func(a slog.Attr) { + fields = append(fields, a.Key, a.Value.String()) + }) + // Get the caller frame using the record's PC. + frames := runtime.CallersFrames([]uintptr{record.PC}) + frame, _ := frames.Next() + l.handle(fromSlogLevel[record.Level], record.Time, []runtime.Frame{frame}, record.Message, fields...) + return nil +} + +// WithAttrs returns a new Handler with the given attributes added. +// +// Implements slog.Handler. +func (l *Logger) WithAttrs(attrs []slog.Attr) slog.Handler { + fields := make([]interface{}, 0, len(attrs)*2) + for _, attr := range attrs { + fields = append(fields, attr.Key, attr.Value) + } + return l.With(fields...) +} + +// WithGroup returns a new Handler with the given group name prepended to the +// current group name or prefix. +// +// Implements slog.Handler. +func (l *Logger) WithGroup(name string) slog.Handler { + if l.prefix != "" { + name = l.prefix + "." + name + } + return l.WithPrefix(name) +} + +var _ slog.Handler = (*Logger)(nil) + func (l *Logger) log(level Level, msg interface{}, keyvals ...interface{}) { if atomic.LoadUint32(&l.isDiscard) != 0 { return @@ -57,24 +107,45 @@ func (l *Logger) log(level Level, msg interface{}, keyvals ...interface{}) { return } - l.mu.Lock() - defer l.mu.Unlock() + var frame runtime.Frame + if l.reportCaller { + // Skip log.log, the caller, and any offset added. + frames := l.frames(l.callerOffset + 2) + for { + f, more := frames.Next() + log.Printf("fillLoc frame: %+v", f) + _, helper := l.helpers.Load(f.Function) + if !helper || !more { + // Found a frame that wasn't a helper function. + // Or we ran out of frames to check. + frame = f + break + } + } + } + l.handle(level, l.timeFunc(), []runtime.Frame{frame}, msg, keyvals...) +} + +func (l *Logger) handle(level Level, ts time.Time, frames []runtime.Frame, msg interface{}, keyvals ...interface{}) { + // l.mu.Lock() + // defer l.mu.Unlock() defer l.b.Reset() var kvs []interface{} - if l.reportTimestamp { - kvs = append(kvs, TimestampKey, l.timeFunc()) + if l.reportTimestamp && !ts.IsZero() { + kvs = append(kvs, TimestampKey, ts) } if level != noLevel { kvs = append(kvs, LevelKey, level) } - if l.reportCaller { - // Call stack is log.Error -> log.log (2) - file, line, fn := l.fillLoc(l.callerOffset + 2) - caller := l.callerFormatter(file, line, fn) - kvs = append(kvs, CallerKey, caller) + if l.reportCaller && len(frames) > 0 && frames[0].PC != 0 { + file, line, fn := l.location(frames) + if file != "" { + caller := l.callerFormatter(file, line, fn) + kvs = append(kvs, CallerKey, caller) + } } if l.prefix != "" { @@ -117,34 +188,33 @@ func (l *Logger) Helper() { } func (l *Logger) helper(skip int) { - _, _, fn := location(skip + 1) - l.helpers.LoadOrStore(fn, struct{}{}) + var pcs [1]uintptr + n := runtime.Callers(skip+2, pcs[:]) + frames := runtime.CallersFrames(pcs[:n]) + frame, _ := frames.Next() + log.Printf("helper frame: %+v", frame) + l.helpers.LoadOrStore(frame.Function, struct{}{}) } -func (l *Logger) fillLoc(skip int) (file string, line int, fn string) { +func (l *Logger) frames(skip int) *runtime.Frames { // Copied from testing.T const maxStackLen = 50 var pc [maxStackLen]uintptr - // Skip two extra frames to account for this function - // and runtime.Callers itself. + // Skip runtime.Callers, and l.frame n := runtime.Callers(skip+2, pc[:]) frames := runtime.CallersFrames(pc[:n]) - for { - frame, more := frames.Next() - _, helper := l.helpers.Load(frame.Function) - if !helper || !more { - // Found a frame that wasn't a helper function. - // Or we ran out of frames to check. - return frame.File, frame.Line, frame.Function - } - } + return frames } -func location(skip int) (file string, line int, fn string) { - pc, file, line, _ := runtime.Caller(skip + 1) - f := runtime.FuncForPC(pc) - return file, line, f.Name() +func (l *Logger) location(frames []runtime.Frame) (file string, line int, fn string) { + // frames := runtime.CallersFrames([]uintptr{pc + 1}) + if len(frames) == 0 { + return "", 0, "" + } + f := frames[0] + log.Printf("location frame: %+v", f) + return f.File, f.Line, f.Function } // Cleanup a path by returning the last n segments of the path only. diff --git a/options_test.go b/options_test.go index 024a221..5199a51 100644 --- a/options_test.go +++ b/options_test.go @@ -28,7 +28,9 @@ func TestOptions(t *testing.T) { func TestCallerFormatter(t *testing.T) { var buf bytes.Buffer l := NewWithOptions(&buf, Options{ReportCaller: true}) - file, line, fn := l.fillLoc(0) + frames := l.frames(0) + frame, _ := frames.Next() + file, line, fn := frame.File, frame.Line, frame.Function hi := func() { l.Info("hi") } cases := []struct { name string @@ -37,12 +39,12 @@ func TestCallerFormatter(t *testing.T) { }{ { name: "short caller formatter", - expected: fmt.Sprintf("INFO hi\n", line+1), + expected: fmt.Sprintf("INFO hi\n", line+3), format: ShortCallerFormatter, }, { name: "long caller formatter", - expected: fmt.Sprintf("INFO <%s:%d> hi\n", file, line+1), + expected: fmt.Sprintf("INFO <%s:%d> hi\n", file, line+3), format: LongCallerFormatter, }, { @@ -54,7 +56,7 @@ func TestCallerFormatter(t *testing.T) { }, { name: "custom caller formatter", - expected: fmt.Sprintf("INFO <%s:%d:%s.func1> hi\n", file, line+1, fn), + expected: fmt.Sprintf("INFO <%s:%d:%s.func1> hi\n", file, line+3, fn), format: func(file string, line int, fn string) string { return fmt.Sprintf("%s:%d:%s", file, line, fn) }, diff --git a/pkg.go b/pkg.go index 9dd2d83..b0e938a 100644 --- a/pkg.go +++ b/pkg.go @@ -131,7 +131,6 @@ func WithPrefix(prefix string) *Logger { // and skips it for source location information. // It's the equivalent of testing.TB.Helper(). func Helper() { - // skip this function frame defaultLogger.helper(1) } diff --git a/pkg_test.go b/pkg_test.go index fcb4727..7003fa1 100644 --- a/pkg_test.go +++ b/pkg_test.go @@ -26,7 +26,7 @@ func TestGlobal(t *testing.T) { }{ { name: "default logger info with timestamp", - expected: "0001/01/01 00:00:00 INFO info\n", + expected: "0002/01/01 00:00:00 INFO info\n", msg: "info", kvs: nil, f: Info, @@ -40,7 +40,7 @@ func TestGlobal(t *testing.T) { }, { name: "default logger error with timestamp", - expected: "0001/01/01 00:00:00 ERRO info\n", + expected: "0002/01/01 00:00:00 ERRO info\n", msg: "info", kvs: nil, f: Error, @@ -65,7 +65,7 @@ func TestPrint(t *testing.T) { SetTimeFormat(DefaultTimeFormat) Error("error") Print("print") - assert.Equal(t, "0001/01/01 00:00:00 print\n", buf.String()) + assert.Equal(t, "0002/01/01 00:00:00 print\n", buf.String()) } func TestPrintf(t *testing.T) { @@ -78,7 +78,7 @@ func TestPrintf(t *testing.T) { SetTimeFormat(DefaultTimeFormat) Errorf("error") Printf("print") - assert.Equal(t, "0001/01/01 00:00:00 print\n", buf.String()) + assert.Equal(t, "0002/01/01 00:00:00 print\n", buf.String()) } func TestFatal(t *testing.T) { @@ -125,7 +125,7 @@ func TestDebugf(t *testing.T) { SetTimeFormat(DefaultTimeFormat) _, file, line, _ := runtime.Caller(0) Debugf("debug %s", "foo") - assert.Equal(t, fmt.Sprintf("0001/01/01 00:00:00 DEBU debug foo\n", filepath.Base(file), line+1), buf.String()) + assert.Equal(t, fmt.Sprintf("0002/01/01 00:00:00 DEBU debug foo\n", filepath.Base(file), line+1), buf.String()) } func TestInfof(t *testing.T) { @@ -148,7 +148,7 @@ func TestWarnf(t *testing.T) { SetTimeFunction(_zeroTime) SetTimeFormat(DefaultTimeFormat) Warnf("warn %s", "foo") - assert.Equal(t, "0001/01/01 00:00:00 WARN warn foo\n", buf.String()) + assert.Equal(t, "0002/01/01 00:00:00 WARN warn foo\n", buf.String()) } func TestErrorf(t *testing.T) { @@ -172,7 +172,7 @@ func TestWith(t *testing.T) { SetTimeFunction(_zeroTime) SetTimeFormat(DefaultTimeFormat) With("foo", "bar").Info("info") - assert.Equal(t, "0001/01/01 00:00:00 INFO info foo=bar\n", buf.String()) + assert.Equal(t, "0002/01/01 00:00:00 INFO info foo=bar\n", buf.String()) } func TestGetLevel(t *testing.T) { diff --git a/text.go b/text.go index 4c0eb48..5c80d80 100644 --- a/text.go +++ b/text.go @@ -124,24 +124,39 @@ func escapeStringForOutput(str string, escapeQuotes bool) string { return bb.String() } -// isNormal indicates if the rune is one allowed to exist as an unquoted -// string value. This is a subset of ASCII, `-` through `~`. -func isNormal(r rune) bool { - return '-' <= r && r <= '~' -} - -// needsQuoting returns false if all the runes in string are normal, according -// to isNormal. -func needsQuoting(str string) bool { - for _, r := range str { - if !isNormal(r) { +func needsQuoting(s string) bool { + for i := 0; i < len(s); { + b := s[i] + if b < utf8.RuneSelf { + if needsQuotingSet[b] { + return true + } + i++ + continue + } + r, size := utf8.DecodeRuneInString(s[i:]) + if r == utf8.RuneError || unicode.IsSpace(r) || !unicode.IsPrint(r) { return true } + i += size } - return false } +var needsQuotingSet = [utf8.RuneSelf]bool{ + '"': true, + '=': true, +} + +func init() { + for i := 0; i < utf8.RuneSelf; i++ { + r := rune(i) + if unicode.IsSpace(r) || !unicode.IsPrint(r) { + needsQuotingSet[i] = true + } + } +} + func (l *Logger) textFormatter(keyvals ...interface{}) { for i := 0; i < len(keyvals); i += 2 { switch keyvals[i] { diff --git a/text_test.go b/text_test.go index d1590e5..895ca8f 100644 --- a/text_test.go +++ b/text_test.go @@ -17,7 +17,7 @@ import ( ) func _zeroTime() time.Time { - return time.Time{} + return time.Time{}.AddDate(1, 0, 0) } func TestTextCaller(t *testing.T) {