feat(logger): implement slog.Handler

This implements slog.Handler interface. You can use Log as an slog
handler.

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 (

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=

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

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

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.

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 <log/options_test.go:%d> hi\n", line+1),
+			expected: fmt.Sprintf("INFO <log/options_test.go:%d> 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)
 			},

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

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 <log/%s:%d> debug foo\n", filepath.Base(file), line+1), buf.String())
+	assert.Equal(t, fmt.Sprintf("0002/01/01 00:00:00 DEBU <log/%s:%d> 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) {