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{
+	if len(options.ContextAttrFuncs) == 0 {
-		opts: options,
+		options.ContextAttrFuncs = logger.DefaultContextAttrFuncs
 	}
 
-	l.leveler = new(slog.LevelVar)
+	attrs, _ := s.argsAttrs(options.Fields)
-	handleOpt := &slog.HandlerOptions{
+	l := &slogLogger{
-		ReplaceAttr: l.renameAttr,
+		handler: &wrapper{h: s.handler.h.WithAttrs(attrs)},
-		Level:       l.leveler,
+		opts:    options,
-		AddSource:   l.opts.AddSource,
 	}
-	l.leveler.Set(loggerToSlogLevel(l.opts.Level))
+	l.handler.level.Store(int64(loggerToSlogLevel(options.Level)))
-	l.handler = slog.New(slog.NewJSONHandler(options.Out, handleOpt)).With(options.Fields...).Handler()
 
 	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{
+	if len(options.ContextAttrFuncs) == 0 {
-		ReplaceAttr: l.renameAttr,
+		options.ContextAttrFuncs = logger.DefaultContextAttrFuncs
-		Level:       l.leveler,
-		AddSource:   l.opts.AddSource,
 	}
 
-	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(

util/time/duration.go

@@ -6,6 +6,8 @@ import (
 	"fmt"
 	"strconv"
 	"time"
+
+	"gopkg.in/yaml.v3"
 )
 
 type Duration int64
@@ -53,6 +55,31 @@ loop:
 	return time.ParseDuration(fmt.Sprintf("%dh%s", hours, s[p:]))
 }
 
+func (d Duration) MarshalYAML() (interface{}, error) {
+	return time.Duration(d).String(), nil
+}
+
+func (d *Duration) UnmarshalYAML(n *yaml.Node) error {
+	var v interface{}
+	if err := yaml.Unmarshal([]byte(n.Value), &v); err != nil {
+		return err
+	}
+	switch value := v.(type) {
+	case float64:
+		*d = Duration(time.Duration(value))
+		return nil
+	case string:
+		dv, err := ParseDuration(value)
+		if err != nil {
+			return err
+		}
+		*d = Duration(dv)
+		return nil
+	default:
+		return fmt.Errorf("invalid duration")
+	}
+}
+
 func (d Duration) MarshalJSON() ([]byte, error) {
 	return json.Marshal(time.Duration(d).String())
 }

util/time/duration_test.go

@@ -5,8 +5,44 @@ import (
 	"encoding/json"
 	"testing"
 	"time"
+
+	"gopkg.in/yaml.v3"
 )
 
+func TestMarshalYAML(t *testing.T) {
+	d := Duration(10000000)
+	buf, err := yaml.Marshal(d)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if !bytes.Equal(buf, []byte(`10ms
+`)) {
+		t.Fatalf("invalid duration: %s != %s", buf, `10ms`)
+	}
+}
+
+func TestUnmarshalYAML(t *testing.T) {
+	type str struct {
+		TTL Duration `yaml:"ttl"`
+	}
+	v := &str{}
+	var err error
+
+	err = yaml.Unmarshal([]byte(`{"ttl":"10ms"}`), v)
+	if err != nil {
+		t.Fatal(err)
+	} else if v.TTL != 10000000 {
+		t.Fatalf("invalid duration %v != 10000000", v.TTL)
+	}
+
+	err = yaml.Unmarshal([]byte(`{"ttl":"1y"}`), v)
+	if err != nil {
+		t.Fatal(err)
+	} else if v.TTL != 31622400000000000 {
+		t.Fatalf("invalid duration %v != 31622400000000000", v.TTL)
+	}
+}
+
 func TestMarshalJSON(t *testing.T) {
 	d := Duration(10000000)
 	buf, err := json.Marshal(d)