logger/slog: fixup race condition #292

Merged
vtolstov merged 2 commits from log into v3 2024-02-22 08:58:41 +03:00
2 changed files with 12 additions and 139 deletions

View File

@ -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())
}
}

View File

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