Merge pull request 'logger/slog: fixup race condition' (#292) from log into v3

Reviewed-on: #292

logger/logger_test.go

@@ -1,138 +0,0 @@
-package logger
-
-import (
-	"bytes"
-	"context"
-	"log"
-	"testing"
-)
-
-func TestContext(t *testing.T) {
-	ctx := context.TODO()
-	buf := bytes.NewBuffer(nil)
-	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
-	if err := l.Init(); err != nil {
-		t.Fatal(err)
-	}
-
-	nl, ok := FromContext(NewContext(ctx, l.Fields("key", "val")))
-	if !ok {
-		t.Fatal("context without logger")
-	}
-	nl.Info(ctx, "message")
-	if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) {
-		t.Fatalf("logger fields not works, buf contains: %s", buf.Bytes())
-	}
-}
-
-func TestFields(t *testing.T) {
-	ctx := context.TODO()
-	buf := bytes.NewBuffer(nil)
-	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
-	if err := l.Init(); err != nil {
-		t.Fatal(err)
-	}
-
-	nl := l.Fields("key", "val")
-
-	nl.Info(ctx, "message")
-	if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) {
-		t.Fatalf("logger fields not works, buf contains: %s", buf.Bytes())
-	}
-}
-
-func TestFromContextWithFields(t *testing.T) {
-	ctx := context.TODO()
-	buf := bytes.NewBuffer(nil)
-	var ok bool
-	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
-	if err := l.Init(); err != nil {
-		t.Fatal(err)
-	}
-	nl := l.Fields("key", "val")
-
-	ctx = NewContext(ctx, nl)
-
-	l, ok = FromContext(ctx)
-	if !ok {
-		t.Fatalf("context does not have logger")
-	}
-
-	l.Info(ctx, "message")
-	if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) {
-		t.Fatalf("logger fields not works, buf contains: %s", buf.Bytes())
-	}
-}
-
-func TestClone(t *testing.T) {
-	ctx := context.TODO()
-	buf := bytes.NewBuffer(nil)
-	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
-	if err := l.Init(); err != nil {
-		t.Fatal(err)
-	}
-	nl := l.Clone(WithLevel(ErrorLevel))
-	if err := nl.Init(); err != nil {
-		t.Fatal(err)
-	}
-	nl.Info(ctx, "info message")
-	if len(buf.Bytes()) != 0 {
-		t.Fatal("message must not be logged")
-	}
-	l.Info(ctx, "info message")
-	if len(buf.Bytes()) == 0 {
-		t.Fatal("message must be logged")
-	}
-}
-
-func TestRedirectStdLogger(t *testing.T) {
-	buf := bytes.NewBuffer(nil)
-	l := NewLogger(WithLevel(TraceLevel), 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"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
-	}
-}
-
-func TestStdLogger(t *testing.T) {
-	buf := bytes.NewBuffer(nil)
-	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
-	if err := l.Init(); err != nil {
-		t.Fatal(err)
-	}
-	lg := NewStdLogger(l, ErrorLevel)
-	lg.Print("test")
-	if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test","timestamp"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
-	}
-}
-
-func TestLogger(t *testing.T) {
-	ctx := context.TODO()
-	buf := bytes.NewBuffer(nil)
-	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
-	if err := l.Init(); err != nil {
-		t.Fatal(err)
-	}
-	l.Trace(ctx, "trace_msg1")
-	l.Warn(ctx, "warn_msg1")
-	l.Fields("error", "test").Info(ctx, "error message")
-	l.Warn(ctx, "first", " ", "second")
-	if !bytes.Contains(buf.Bytes(), []byte(`"level":"trace","msg":"trace_msg1"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
-	}
-	if !bytes.Contains(buf.Bytes(), []byte(`"warn","msg":"warn_msg1"`)) {
-		t.Fatalf("logger error, 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())
-	}
-	if !bytes.Contains(buf.Bytes(), []byte(`"level":"warn","msg":"first second"`)) {
-		t.Fatalf("logger error, buf %s", buf.Bytes())
-	}
-}

logger/slog/slog.go

@@ -7,6 +7,7 @@ import (
 	"os"
 	"runtime"
 	"strconv"
+	"sync"
 	"time"
 
 	"go.unistack.org/micro/v3/logger"
@@ -72,9 +73,11 @@ type slogLogger struct {
 	sourceKey  string
 	timeKey    string
 	opts       logger.Options
+	mu         sync.RWMutex
 }
 
 func (s *slogLogger) Clone(opts ...logger.Option) logger.Logger {
+	s.mu.RLock()
 	options := s.opts
 
 	for _, o := range opts {
@@ -112,6 +115,8 @@ func (s *slogLogger) Clone(opts ...logger.Option) logger.Logger {
 	handler := slog.NewJSONHandler(options.Out, handleOpt)
 	l.slog = slog.New(handler).With(options.Fields...)
 
+	s.mu.RUnlock()
+
 	return l
 }
 
@@ -128,6 +133,7 @@ func (s *slogLogger) Options() logger.Options {
 }
 
 func (s *slogLogger) Fields(attrs ...interface{}) logger.Logger {
+	s.mu.RLock()
 	nl := &slogLogger{
 		opts:       s.opts,
 		levelKey:   s.levelKey,
@@ -140,17 +146,20 @@ func (s *slogLogger) Fields(attrs ...interface{}) logger.Logger {
 
 	handleOpt := &slog.HandlerOptions{
 		ReplaceAttr: nl.renameAttr,
-		Level:       s.leveler,
+		Level:       nl.leveler,
 		AddSource:   true,
 	}
 
 	handler := slog.NewJSONHandler(s.opts.Out, handleOpt)
 	nl.slog = slog.New(handler).With(attrs...)
 
+	s.mu.RUnlock()
+
 	return nl
 }
 
 func (s *slogLogger) Init(opts ...logger.Option) error {
+	s.mu.Lock()
 	for _, o := range opts {
 		o(&s.opts)
 	}
@@ -180,6 +189,8 @@ func (s *slogLogger) Init(opts ...logger.Option) error {
 
 	slog.SetDefault(s.slog)
 
+	s.mu.Unlock()
+
 	return nil
 }