logger/slog: fix race condigtion with Enabled and Level

Signed-off-by: Vasiliy Tolstov <v.tolstov@unistack.org>

logger/slog/slog.go

@@ -8,6 +8,7 @@ import (
 	"runtime"
 	"strconv"
 	"sync"
+	"sync/atomic"
 
 	"go.unistack.org/micro/v3/logger"
 	"go.unistack.org/micro/v3/semconv"
@@ -31,6 +32,27 @@ var (
 	fatalValue = slog.StringValue("fatal")
 )
 
+type wrapper struct {
+	h     slog.Handler
+	level atomic.Int64
+}
+
+func (h *wrapper) Enabled(ctx context.Context, level slog.Level) bool {
+	return level >= slog.Level(int(h.level.Load()))
+}
+
+func (h *wrapper) Handle(ctx context.Context, rec slog.Record) error {
+	return h.h.Handle(ctx, rec)
+}
+
+func (h *wrapper) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return h.WithAttrs(attrs)
+}
+
+func (h *wrapper) WithGroup(name string) slog.Handler {
+	return h.WithGroup(name)
+}
+
 func (s *slogLogger) renameAttr(_ []string, a slog.Attr) slog.Attr {
 	switch a.Key {
 	case slog.SourceKey:
@@ -68,7 +90,7 @@ func (s *slogLogger) renameAttr(_ []string, a slog.Attr) slog.Attr {
 
 type slogLogger struct {
 	leveler *slog.LevelVar
-	handler slog.Handler
+	handler *wrapper
 	opts    logger.Options
 	mu      sync.RWMutex
 }
@@ -82,51 +104,52 @@ func (s *slogLogger) Clone(opts ...logger.Option) logger.Logger {
 		o(&options)
 	}
 
-	l := &slogLogger{
-		opts: options,
+	if len(options.ContextAttrFuncs) == 0 {
+		options.ContextAttrFuncs = logger.DefaultContextAttrFuncs
 	}
 
-	l.leveler = new(slog.LevelVar)
-	handleOpt := &slog.HandlerOptions{
-		ReplaceAttr: l.renameAttr,
-		Level:       l.leveler,
-		AddSource:   l.opts.AddSource,
+	attrs, _ := s.argsAttrs(options.Fields)
+	l := &slogLogger{
+		handler: &wrapper{h: s.handler.h.WithAttrs(attrs)},
+		opts:    options,
 	}
-	l.leveler.Set(loggerToSlogLevel(l.opts.Level))
-	l.handler = slog.New(slog.NewJSONHandler(options.Out, handleOpt)).With(options.Fields...).Handler()
+	l.handler.level.Store(int64(loggerToSlogLevel(options.Level)))
 
 	return l
 }
 
 func (s *slogLogger) V(level logger.Level) bool {
-	return s.opts.Level.Enabled(level)
+	s.mu.Lock()
+	v := s.opts.Level.Enabled(level)
+	s.mu.Unlock()
+	return v
 }
 
 func (s *slogLogger) Level(level logger.Level) {
-	s.leveler.Set(loggerToSlogLevel(level))
+	s.mu.Lock()
+	s.opts.Level = level
+	s.handler.level.Store(int64(loggerToSlogLevel(level)))
+	s.mu.Unlock()
 }
 
 func (s *slogLogger) Options() logger.Options {
 	return s.opts
 }
 
-func (s *slogLogger) Fields(attrs ...interface{}) logger.Logger {
+func (s *slogLogger) Fields(fields ...interface{}) logger.Logger {
 	s.mu.RLock()
-	level := s.leveler.Level()
 	options := s.opts
 	s.mu.RUnlock()
 
 	l := &slogLogger{opts: options}
-	l.leveler = new(slog.LevelVar)
-	l.leveler.Set(level)
 
-	handleOpt := &slog.HandlerOptions{
-		ReplaceAttr: l.renameAttr,
-		Level:       l.leveler,
-		AddSource:   l.opts.AddSource,
+	if len(options.ContextAttrFuncs) == 0 {
+		options.ContextAttrFuncs = logger.DefaultContextAttrFuncs
 	}
 
-	l.handler = slog.New(slog.NewJSONHandler(l.opts.Out, handleOpt)).With(attrs...).Handler()
+	attrs, _ := s.argsAttrs(fields)
+	l.handler = &wrapper{h: s.handler.h.WithAttrs(attrs)}
+	l.handler.level.Store(int64(loggerToSlogLevel(l.opts.Level)))
 
 	return l
 }
@@ -134,22 +157,23 @@ func (s *slogLogger) Fields(attrs ...interface{}) logger.Logger {
 func (s *slogLogger) Init(opts ...logger.Option) error {
 	s.mu.Lock()
 
-	if len(s.opts.ContextAttrFuncs) == 0 {
-		s.opts.ContextAttrFuncs = logger.DefaultContextAttrFuncs
-	}
-
 	for _, o := range opts {
 		o(&s.opts)
 	}
 
-	s.leveler = new(slog.LevelVar)
+	if len(s.opts.ContextAttrFuncs) == 0 {
+		s.opts.ContextAttrFuncs = logger.DefaultContextAttrFuncs
+	}
+
 	handleOpt := &slog.HandlerOptions{
 		ReplaceAttr: s.renameAttr,
-		Level:       s.leveler,
+		Level:       loggerToSlogLevel(logger.TraceLevel),
 		AddSource:   s.opts.AddSource,
 	}
-	s.leveler.Set(loggerToSlogLevel(s.opts.Level))
-	s.handler = slog.New(slog.NewJSONHandler(s.opts.Out, handleOpt)).With(s.opts.Fields...).Handler()
+
+	attrs, _ := s.argsAttrs(s.opts.Fields)
+	s.handler = &wrapper{h: slog.NewJSONHandler(s.opts.Out, handleOpt).WithAttrs(attrs)}
+	s.handler.level.Store(int64(loggerToSlogLevel(s.opts.Level)))
 	s.mu.Unlock()
 
 	return nil

logger/slog/slog_test.go

@@ -15,6 +15,56 @@ import (
 	"go.unistack.org/micro/v3/logger"
 )
 
+func TestMultipleFieldsWithLevel(t *testing.T) {
+	ctx := context.TODO()
+	buf := bytes.NewBuffer(nil)
+	l := NewLogger(logger.WithLevel(logger.InfoLevel), logger.WithOutput(buf))
+	if err := l.Init(); err != nil {
+		t.Fatal(err)
+	}
+
+	l = l.Fields("key", "val")
+
+	l.Info(ctx, "msg1")
+	nl := l.Clone(logger.WithLevel(logger.DebugLevel))
+	nl.Debug(ctx, "msg2")
+	l.Debug(ctx, "msg3")
+	if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) {
+		t.Fatalf("logger error not works, buf contains: %s", buf.Bytes())
+	}
+	if !bytes.Contains(buf.Bytes(), []byte(`"msg1"`)) {
+		t.Fatalf("logger error not works, buf contains: %s", buf.Bytes())
+	}
+	if !bytes.Contains(buf.Bytes(), []byte(`"msg2"`)) {
+		t.Fatalf("logger error not works, buf contains: %s", buf.Bytes())
+	}
+	if bytes.Contains(buf.Bytes(), []byte(`"msg3"`)) {
+		t.Fatalf("logger error not works, buf contains: %s", buf.Bytes())
+	}
+}
+
+func TestMultipleFields(t *testing.T) {
+	ctx := context.TODO()
+	buf := bytes.NewBuffer(nil)
+	l := NewLogger(logger.WithLevel(logger.InfoLevel), logger.WithOutput(buf))
+	if err := l.Init(); err != nil {
+		t.Fatal(err)
+	}
+
+	l = l.Fields("key", "val")
+
+	l = l.Fields("key1", "val1")
+
+	l.Info(ctx, "msg")
+
+	if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) {
+		t.Fatalf("logger error not works, buf contains: %s", buf.Bytes())
+	}
+	if !bytes.Contains(buf.Bytes(), []byte(`"key1":"val1"`)) {
+		t.Fatalf("logger error not works, buf contains: %s", buf.Bytes())
+	}
+}
+
 func TestError(t *testing.T) {
 	ctx := context.TODO()
 	buf := bytes.NewBuffer(nil)
@@ -234,4 +284,11 @@ func Test_WithContextAttrFunc(t *testing.T) {
 	if !(bytes.Contains(buf.Bytes(), []byte(`"source-service":"Test-System"`))) {
 		t.Fatalf("logger info, buf %s", buf.Bytes())
 	}
+	buf.Reset()
+	imd, _ := metadata.FromIncomingContext(ctx)
+	l.Info(ctx, "test message1")
+	imd.Set("Source-Service", "Test-System2")
+	l.Info(ctx, "test message2")
+
+	// t.Logf("xxx %s", buf.Bytes())
 }

service.go

@@ -6,7 +6,7 @@ import (
 	"sync"
 
 	"github.com/KimMachineGun/automemlimit/memlimit"
-	_ "go.uber.org/automaxprocs"
+	"go.uber.org/automaxprocs/maxprocs"
 	"go.unistack.org/micro/v3/broker"
 	"go.unistack.org/micro/v3/client"
 	"go.unistack.org/micro/v3/config"
@@ -20,6 +20,7 @@ import (
 )
 
 func init() {
+	maxprocs.Set()
 	memlimit.SetGoMemLimitWithOpts(
 		memlimit.WithRatio(0.9),
 		memlimit.WithProvider(