From 8e2eafde9c48328f56c889886615ae284fff5c9e Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Thu, 22 Feb 2024 08:57:21 +0300 Subject: [PATCH] logger/slog: fixup race condition Signed-off-by: Vasiliy Tolstov --- logger/logger_test.go | 138 ------------------------------------------ logger/slog/slog.go | 11 ++++ 2 files changed, 11 insertions(+), 138 deletions(-) delete mode 100644 logger/logger_test.go diff --git a/logger/logger_test.go b/logger/logger_test.go deleted file mode 100644 index b9b8146d..00000000 --- a/logger/logger_test.go +++ /dev/null @@ -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()) - } -} diff --git a/logger/slog/slog.go b/logger/slog/slog.go index 2c0ac7c3..6e12b65e 100644 --- a/logger/slog/slog.go +++ b/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, @@ -147,10 +153,13 @@ func (s *slogLogger) Fields(attrs ...interface{}) logger.Logger { 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 }