Merge pull request 'logger: slog logger' (#266) from slog into master

Reviewed-on: #266

go.mod

@@ -8,6 +8,7 @@ require (
 	github.com/google/uuid v1.3.1
 	github.com/patrickmn/go-cache v2.1.0+incompatible
 	github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5
+	golang.org/x/exp v0.0.0-20230905200255-921286631fa9
 	golang.org/x/sync v0.3.0
 	golang.org/x/sys v0.12.0
 	google.golang.org/grpc v1.58.2

go.sum

@@ -13,6 +13,8 @@ github.com/patrickmn/go-cache v2.1.0+incompatible h1:HRMgzkcYKYpi3C8ajMPV8OFXaaR
 github.com/patrickmn/go-cache v2.1.0+incompatible/go.mod h1:3Qf8kWWT7OJRJbdiICTKqZju1ZixQ/KpMGzzAfe6+WQ=
 github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5 h1:G/FZtUu7a6NTWl3KUHMV9jkLAh/Rvtf03NWMHaEDl+E=
 github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5/go.mod h1:7RTUFBdIRC9nZ7/3RyRNH1bdqIShrDejd1YbLwgPS+I=
+golang.org/x/exp v0.0.0-20230905200255-921286631fa9 h1:GoHiUyI/Tp2nVkLI2mCxVkOjsbSXD66ic0XW0js0R9g=
+golang.org/x/exp v0.0.0-20230905200255-921286631fa9/go.mod h1:S2oDrQGGwySpoQPVqRShND87VCbxmc6bL1Yd2oYrm6k=
 golang.org/x/net v0.15.0 h1:ugBLEUaxABaB5AJqW9enI0ACdci2RUd4eP51NTBvuJ8=
 golang.org/x/net v0.15.0/go.mod h1:idbUs1IY1+zTqbi8yxTbhexhEEk5ur9LInksu6HrEpk=
 golang.org/x/sync v0.3.0 h1:ftCYgMx6zT/asHUrPw8BLLscYtGznsLAnjq5RH9P66E=

logger/default.go

@@ -1,232 +0,0 @@
-package logger
-
-import (
-	"context"
-	"encoding/json"
-	"fmt"
-	"os"
-	"runtime"
-	"strings"
-	"sync"
-	"time"
-
-	"go.unistack.org/micro/v4/options"
-)
-
-type defaultLogger struct {
-	enc  *json.Encoder
-	opts Options
-	sync.RWMutex
-}
-
-// Init(opts...) should only overwrite provided options
-func (l *defaultLogger) Init(opts ...options.Option) error {
-	l.Lock()
-	for _, o := range opts {
-		o(&l.opts)
-	}
-	l.enc = json.NewEncoder(l.opts.Out)
-	// wrap the Log func
-	l.Unlock()
-	return nil
-}
-
-func (l *defaultLogger) String() string {
-	return "micro"
-}
-
-func (l *defaultLogger) Clone(opts ...options.Option) Logger {
-	newopts := NewOptions(opts...)
-	oldopts := l.opts
-	for _, o := range opts {
-		o(&newopts)
-		o(&oldopts)
-	}
-
-	l.Lock()
-	cl := &defaultLogger{opts: oldopts, enc: json.NewEncoder(l.opts.Out)}
-	l.Unlock()
-
-	return cl
-}
-
-func (l *defaultLogger) V(level Level) bool {
-	l.RLock()
-	ok := l.opts.Level.Enabled(level)
-	l.RUnlock()
-	return ok
-}
-
-func (l *defaultLogger) Level(level Level) {
-	l.Lock()
-	l.opts.Level = level
-	l.Unlock()
-}
-
-func (l *defaultLogger) Fields(fields ...interface{}) Logger {
-	l.RLock()
-	nl := &defaultLogger{opts: l.opts, enc: l.enc}
-	if len(fields) == 0 {
-		l.RUnlock()
-		return nl
-	} else if len(fields)%2 != 0 {
-		fields = fields[:len(fields)-1]
-	}
-	nl.opts.Fields = copyFields(l.opts.Fields)
-	nl.opts.Fields = append(nl.opts.Fields, fields...)
-	l.RUnlock()
-	return nl
-}
-
-func copyFields(src []interface{}) []interface{} {
-	dst := make([]interface{}, len(src))
-	copy(dst, src)
-	return dst
-}
-
-// logCallerfilePath returns a package/file:line description of the caller,
-// preserving only the leaf directory name and file name.
-func logCallerfilePath(loggingFilePath string) string {
-	// To make sure we trim the path correctly on Windows too, we
-	// counter-intuitively need to use '/' and *not* os.PathSeparator here,
-	// because the path given originates from Go stdlib, specifically
-	// runtime.Caller() which (as of Mar/17) returns forward slashes even on
-	// Windows.
-	//
-	// See https://github.com/golang/go/issues/3335
-	// and https://github.com/golang/go/issues/18151
-	//
-	// for discussion on the issue on Go side.
-	idx := strings.LastIndexByte(loggingFilePath, '/')
-	if idx == -1 {
-		return loggingFilePath
-	}
-	idx = strings.LastIndexByte(loggingFilePath[:idx], '/')
-	if idx == -1 {
-		return loggingFilePath
-	}
-	return loggingFilePath[idx+1:]
-}
-
-func (l *defaultLogger) Info(ctx context.Context, args ...interface{}) {
-	l.Log(ctx, InfoLevel, args...)
-}
-
-func (l *defaultLogger) Error(ctx context.Context, args ...interface{}) {
-	l.Log(ctx, ErrorLevel, args...)
-}
-
-func (l *defaultLogger) Debug(ctx context.Context, args ...interface{}) {
-	l.Log(ctx, DebugLevel, args...)
-}
-
-func (l *defaultLogger) Warn(ctx context.Context, args ...interface{}) {
-	l.Log(ctx, WarnLevel, args...)
-}
-
-func (l *defaultLogger) Trace(ctx context.Context, args ...interface{}) {
-	l.Log(ctx, TraceLevel, args...)
-}
-
-func (l *defaultLogger) Fatal(ctx context.Context, args ...interface{}) {
-	l.Log(ctx, FatalLevel, args...)
-	os.Exit(1)
-}
-
-func (l *defaultLogger) Infof(ctx context.Context, msg string, args ...interface{}) {
-	l.Logf(ctx, InfoLevel, msg, args...)
-}
-
-func (l *defaultLogger) Errorf(ctx context.Context, msg string, args ...interface{}) {
-	l.Logf(ctx, ErrorLevel, msg, args...)
-}
-
-func (l *defaultLogger) Debugf(ctx context.Context, msg string, args ...interface{}) {
-	l.Logf(ctx, DebugLevel, msg, args...)
-}
-
-func (l *defaultLogger) Warnf(ctx context.Context, msg string, args ...interface{}) {
-	l.Logf(ctx, WarnLevel, msg, args...)
-}
-
-func (l *defaultLogger) Tracef(ctx context.Context, msg string, args ...interface{}) {
-	l.Logf(ctx, TraceLevel, msg, args...)
-}
-
-func (l *defaultLogger) Fatalf(ctx context.Context, msg string, args ...interface{}) {
-	l.Logf(ctx, FatalLevel, msg, args...)
-	os.Exit(1)
-}
-
-func (l *defaultLogger) Log(ctx context.Context, level Level, args ...interface{}) {
-	if !l.V(level) {
-		return
-	}
-
-	l.RLock()
-	fields := copyFields(l.opts.Fields)
-	l.RUnlock()
-
-	fields = append(fields, "level", level.String())
-
-	if _, file, line, ok := runtime.Caller(l.opts.CallerSkipCount); ok {
-		fields = append(fields, "caller", fmt.Sprintf("%s:%d", logCallerfilePath(file), line))
-	}
-	fields = append(fields, "timestamp", time.Now().Format("2006-01-02 15:04:05"))
-
-	if len(args) > 0 {
-		fields = append(fields, "msg", fmt.Sprint(args...))
-	}
-
-	out := make(map[string]interface{}, len(fields)/2)
-	for i := 0; i < len(fields); i += 2 {
-		out[fields[i].(string)] = fields[i+1]
-	}
-	l.RLock()
-	_ = l.enc.Encode(out)
-	l.RUnlock()
-}
-
-func (l *defaultLogger) Logf(ctx context.Context, level Level, msg string, args ...interface{}) {
-	if !l.V(level) {
-		return
-	}
-
-	l.RLock()
-	fields := copyFields(l.opts.Fields)
-	l.RUnlock()
-
-	fields = append(fields, "level", level.String())
-
-	if _, file, line, ok := runtime.Caller(l.opts.CallerSkipCount); ok {
-		fields = append(fields, "caller", fmt.Sprintf("%s:%d", logCallerfilePath(file), line))
-	}
-
-	fields = append(fields, "timestamp", time.Now().Format("2006-01-02 15:04:05"))
-	if len(args) > 0 {
-		fields = append(fields, "msg", fmt.Sprintf(msg, args...))
-	} else if msg != "" {
-		fields = append(fields, "msg", msg)
-	}
-
-	out := make(map[string]interface{}, len(fields)/2)
-	for i := 0; i < len(fields); i += 2 {
-		out[fields[i].(string)] = fields[i+1]
-	}
-	l.RLock()
-	_ = l.enc.Encode(out)
-	l.RUnlock()
-}
-
-func (l *defaultLogger) Options() Options {
-	return l.opts
-}
-
-// NewLogger builds a new logger based on options
-func NewLogger(opts ...options.Option) Logger {
-	l := &defaultLogger{
-		opts: NewOptions(opts...),
-	}
-	l.enc = json.NewEncoder(l.opts.Out)
-	return l
-}

logger/logger_test.go

@@ -87,14 +87,14 @@ func TestClone(t *testing.T) {
 
 func TestRedirectStdLogger(t *testing.T) {
 	buf := bytes.NewBuffer(nil)
-	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
+	l := NewLogger(WithLevel(ErrorLevel), WithOutput(buf))
 	if err := l.Init(); err != nil {
 		t.Fatal(err)
 	}
 	fn := RedirectStdLogger(l, ErrorLevel)
 	defer fn()
 	log.Print("test")
-	if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test","timestamp"`)) {
+	if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test"`)) {
 		t.Fatalf("logger error, buf %s", buf.Bytes())
 	}
 }
@@ -107,7 +107,7 @@ func TestStdLogger(t *testing.T) {
 	}
 	lg := NewStdLogger(l, ErrorLevel)
 	lg.Print("test")
-	if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test","timestamp"`)) {
+	if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test"`)) {
 		t.Fatalf("logger error, buf %s", buf.Bytes())
 	}
 }
@@ -120,19 +120,21 @@ func TestLogger(t *testing.T) {
 		t.Fatal(err)
 	}
 	l.Trace(ctx, "trace_msg1")
-	l.Warn(ctx, "warn_msg1")
+	//	l.Warn(ctx, "warn_msg1")
-	l.Fields("error", "test").Info(ctx, "error message")
+	//	l.Fields("error", "test").Info(ctx, "error message")
-	l.Warn(ctx, "first", " ", "second")
+	//	l.Warn(ctx, "first second")
 	if !bytes.Contains(buf.Bytes(), []byte(`"level":"trace","msg":"trace_msg1"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
+		t.Fatalf("logger tracer, buf %s", buf.Bytes())
 	}
+	/*
 		if !bytes.Contains(buf.Bytes(), []byte(`"warn","msg":"warn_msg1"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
+			t.Fatalf("logger warn, buf %s", buf.Bytes())
 		}
 		if !bytes.Contains(buf.Bytes(), []byte(`"error":"test","level":"info","msg":"error message"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
+			t.Fatalf("logger info, buf %s", buf.Bytes())
 		}
 		if !bytes.Contains(buf.Bytes(), []byte(`"level":"warn","msg":"first second"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
+			t.Fatalf("logger warn, buf %s", buf.Bytes())
 		}
+	*/
 }

logger/slog.go

@@ -0,0 +1,245 @@
+package logger
+
+import (
+	"context"
+	"fmt"
+	"os"
+
+	"go.unistack.org/micro/v4/options"
+
+	"golang.org/x/exp/slog"
+)
+
+var (
+	traceValue = slog.StringValue("trace")
+	debugValue = slog.StringValue("debug")
+	infoValue  = slog.StringValue("info")
+	warnValue  = slog.StringValue("warn")
+	errorValue = slog.StringValue("error")
+	fatalValue = slog.StringValue("fatal")
+)
+
+var renameAttr = func(_ []string, a slog.Attr) slog.Attr {
+	switch a.Key {
+	case slog.TimeKey:
+		a.Key = "timestamp"
+	case slog.LevelKey:
+		level := a.Value.Any().(slog.Level)
+		lvl := slogToLoggerLevel(level)
+		switch {
+		case lvl < DebugLevel:
+			a.Value = traceValue
+		case lvl < InfoLevel:
+			a.Value = debugValue
+		case lvl < WarnLevel:
+			a.Value = infoValue
+		case lvl < ErrorLevel:
+			a.Value = warnValue
+		case lvl < FatalLevel:
+			a.Value = errorValue
+		case lvl >= FatalLevel:
+			a.Value = fatalValue
+		default:
+			a.Value = infoValue
+		}
+	}
+
+	return a
+}
+
+type slogLogger struct {
+	slog    *slog.Logger
+	leveler *slog.LevelVar
+	opts    Options
+}
+
+func (s *slogLogger) Clone(opts ...options.Option) Logger {
+	options := s.opts
+
+	for _, o := range opts {
+		o(&options)
+	}
+
+	l := &slogLogger{
+		opts: options,
+	}
+
+	if slog, ok := s.opts.Context.Value(loggerKey{}).(*slog.Logger); ok {
+		l.slog = slog
+		return nil
+	}
+
+	l.leveler = new(slog.LevelVar)
+	handleOpt := &slog.HandlerOptions{
+		ReplaceAttr: renameAttr,
+		Level:       l.leveler,
+	}
+	l.leveler.Set(loggerToSlogLevel(l.opts.Level))
+	handler := slog.NewJSONHandler(options.Out, handleOpt)
+	l.slog = slog.New(handler).With(options.Fields...)
+
+	return l
+}
+
+func (s *slogLogger) V(level Level) bool {
+	return s.opts.Level.Enabled(level)
+}
+
+func (s *slogLogger) Level(level Level) {
+	s.leveler.Set(loggerToSlogLevel(level))
+}
+
+func (s *slogLogger) Options() Options {
+	return s.opts
+}
+
+func (s *slogLogger) Fields(fields ...interface{}) Logger {
+	nl := &slogLogger{opts: s.opts}
+	nl.leveler = new(slog.LevelVar)
+	nl.leveler.Set(s.leveler.Level())
+
+	handleOpt := &slog.HandlerOptions{
+		ReplaceAttr: renameAttr,
+		Level:       s.leveler,
+	}
+
+	handler := slog.NewJSONHandler(s.opts.Out, handleOpt)
+	nl.slog = slog.New(handler).With(fields...)
+
+	return nl
+}
+
+func (s *slogLogger) Init(opts ...options.Option) error {
+	for _, o := range opts {
+		if err := o(&s.opts); err != nil {
+			return err
+		}
+	}
+
+	if slog, ok := s.opts.Context.Value(loggerKey{}).(*slog.Logger); ok {
+		s.slog = slog
+		return nil
+	}
+
+	s.leveler = new(slog.LevelVar)
+	handleOpt := &slog.HandlerOptions{
+		ReplaceAttr: renameAttr,
+		Level:       s.leveler,
+	}
+	s.leveler.Set(loggerToSlogLevel(s.opts.Level))
+	handler := slog.NewJSONHandler(s.opts.Out, handleOpt)
+	s.slog = slog.New(handler).With(s.opts.Fields...)
+
+	return nil
+}
+
+func (s *slogLogger) Log(ctx context.Context, lvl Level, args ...any) {
+	if !s.V(lvl) {
+		return
+	}
+	slvl := loggerToSlogLevel(lvl)
+	msg := fmt.Sprint(args...)
+	s.slog.Log(ctx, slvl, msg)
+}
+
+func (s *slogLogger) Logf(ctx context.Context, lvl Level, format string, args ...any) {
+	if !s.V(lvl) {
+		return
+	}
+	slvl := loggerToSlogLevel(lvl)
+	s.slog.Log(ctx, slvl, format, args...)
+}
+
+func (s *slogLogger) Info(ctx context.Context, args ...any) {
+	s.Log(ctx, InfoLevel, args...)
+}
+
+func (s *slogLogger) Infof(ctx context.Context, format string, args ...interface{}) {
+	s.Logf(ctx, InfoLevel, format, args...)
+}
+
+func (s *slogLogger) Debug(ctx context.Context, args ...any) {
+	s.Log(ctx, DebugLevel, args...)
+}
+
+func (s *slogLogger) Debugf(ctx context.Context, format string, args ...any) {
+	s.Logf(ctx, DebugLevel, format, args...)
+}
+
+func (s *slogLogger) Error(ctx context.Context, args ...any) {
+	s.Log(ctx, ErrorLevel, args...)
+}
+
+func (s *slogLogger) Trace(ctx context.Context, args ...interface{}) {
+	s.Log(ctx, TraceLevel, args...)
+}
+
+func (s *slogLogger) Tracef(ctx context.Context, msg string, args ...interface{}) {
+	s.Logf(ctx, TraceLevel, msg, args...)
+}
+
+func (s *slogLogger) Errorf(ctx context.Context, format string, args ...any) {
+	s.Logf(ctx, ErrorLevel, format, args...)
+}
+
+func (s *slogLogger) Fatal(ctx context.Context, args ...any) {
+	s.Log(ctx, FatalLevel, args...)
+}
+
+func (s *slogLogger) Fatalf(ctx context.Context, msg string, args ...interface{}) {
+	s.Logf(ctx, FatalLevel, msg, args...)
+	os.Exit(1)
+}
+
+func (s *slogLogger) Warn(ctx context.Context, args ...any) {
+	s.Log(ctx, WarnLevel, args...)
+}
+
+func (s *slogLogger) Warnf(ctx context.Context, format string, args ...any) {
+	s.Logf(ctx, WarnLevel, format, args...)
+}
+
+func (s *slogLogger) String() string {
+	return "slog"
+}
+
+func NewLogger(opts ...options.Option) Logger {
+	l := &slogLogger{
+		opts: NewOptions(opts...),
+	}
+	return l
+}
+
+func loggerToSlogLevel(level Level) slog.Level {
+	switch level {
+	case DebugLevel:
+		return slog.LevelDebug
+	case WarnLevel:
+		return slog.LevelWarn
+	case ErrorLevel:
+		return slog.LevelError
+	case TraceLevel:
+		return slog.LevelDebug - 1
+	case FatalLevel:
+		return slog.LevelError + 1
+	default:
+		return slog.LevelInfo
+	}
+}
+
+func slogToLoggerLevel(level slog.Level) Level {
+	switch level {
+	case slog.LevelDebug:
+		return DebugLevel
+	case slog.LevelWarn:
+		return WarnLevel
+	case slog.LevelError:
+		return ErrorLevel
+	case slog.LevelDebug - 1:
+		return TraceLevel
+	case slog.LevelError + 1:
+		return FatalLevel
+	default:
+		return InfoLevel
+	}
+}

tracer/options.go

@@ -2,9 +2,11 @@ package tracer
 
 import (
 	"context"
+	"reflect"
 
 	"go.unistack.org/micro/v4/logger"
 	"go.unistack.org/micro/v4/options"
+	rutil "go.unistack.org/micro/v4/util/reflect"
 )
 
 type SpanStatus int
@@ -93,6 +95,43 @@ type EventOptions struct {
 	Labels []interface{}
 }
 
+func WithSpanLabels(ls ...interface{}) options.Option {
+	return func(src interface{}) error {
+		v, err := options.Get(src, ".Labels")
+		if err != nil {
+			return err
+		} else if rutil.IsZero(v) {
+			v = reflect.MakeSlice(reflect.TypeOf(v), 0, len(ls)).Interface()
+		}
+		cv := reflect.ValueOf(v)
+		for _, l := range ls {
+			reflect.Append(cv, reflect.ValueOf(l))
+		}
+		err = options.Set(src, cv, ".Labels")
+		return err
+	}
+}
+
+// EventOption func signature
+type EventOption func(o *EventOptions)
+
+func WithEventLabels(ls ...interface{}) options.Option {
+	return func(src interface{}) error {
+		v, err := options.Get(src, ".Labels")
+		if err != nil {
+			return err
+		} else if rutil.IsZero(v) {
+			v = reflect.MakeSlice(reflect.TypeOf(v), 0, len(ls)).Interface()
+		}
+		cv := reflect.ValueOf(v)
+		for _, l := range ls {
+			reflect.Append(cv, reflect.ValueOf(l))
+		}
+		err = options.Set(src, cv, ".Labels")
+		return err
+	}
+}
+
 func WithSpanKind(k SpanKind) options.Option {
 	return func(src interface{}) error {
 		return options.Set(src, k, ".Kind")

tracer/wrapper/wrapper.go

@@ -13,7 +13,7 @@ import (
 	"go.unistack.org/micro/v4/tracer"
 )
 
-var DefaultHeadersExctract = []string{metadata.HeaderXRequestID}
+var DefaultHeadersExctract = []string{metadata.HeaderTopic, metadata.HeaderEndpoint, metadata.HeaderService, metadata.HeaderXRequestID}
 
 func ExtractDefaultLabels(md metadata.Metadata) []interface{} {
 	labels := make([]interface{}, 0, len(DefaultHeadersExctract))
@@ -27,6 +27,7 @@ func ExtractDefaultLabels(md metadata.Metadata) []interface{} {
 
 var (
 	DefaultClientCallObserver = func(ctx context.Context, req client.Request, rsp interface{}, opts []options.Option, sp tracer.Span, err error) {
+		sp.SetName(fmt.Sprintf("Call %s.%s", req.Service(), req.Method()))
 		var labels []interface{}
 		if md, ok := metadata.FromOutgoingContext(ctx); ok {
 			labels = append(labels, ExtractDefaultLabels(md)...)