From 1acaa898a221764e7d9c4e280b22c45a4d1fed64 Mon Sep 17 00:00:00 2001 From: devstigneev Date: Wed, 2 Oct 2024 18:03:56 +0300 Subject: [PATCH 01/10] update logic prepare msg for output logs fix changes add prepare Attributes in slog/logger --- go.mod | 1 + go.sum | 2 + logger/logger.go | 15 ++- logger/options.go | 4 +- logger/slog/slog.go | 224 ++++++++++++--------------------------- logger/slog/slog_test.go | 22 +++- 6 files changed, 101 insertions(+), 167 deletions(-) diff --git a/go.mod b/go.mod index 5dd808cb..8beaa10e 100644 --- a/go.mod +++ b/go.mod @@ -8,6 +8,7 @@ require ( github.com/google/uuid v1.3.0 github.com/patrickmn/go-cache v2.1.0+incompatible github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5 + go.unistack.org/micro-proto/v3 v3.4.1 golang.org/x/sync v0.3.0 google.golang.org/grpc v1.57.0 google.golang.org/protobuf v1.31.0 diff --git a/go.sum b/go.sum index 5f3145b9..4268c0d3 100644 --- a/go.sum +++ b/go.sum @@ -13,6 +13,8 @@ github.com/patrickmn/go-cache v2.1.0+incompatible h1:HRMgzkcYKYpi3C8ajMPV8OFXaaR github.com/patrickmn/go-cache v2.1.0+incompatible/go.mod h1:3Qf8kWWT7OJRJbdiICTKqZju1ZixQ/KpMGzzAfe6+WQ= github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5 h1:G/FZtUu7a6NTWl3KUHMV9jkLAh/Rvtf03NWMHaEDl+E= github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5/go.mod h1:7RTUFBdIRC9nZ7/3RyRNH1bdqIShrDejd1YbLwgPS+I= +go.unistack.org/micro-proto/v3 v3.4.1 h1:UTjLSRz2YZuaHk9iSlVqqsA50JQNAEK2ZFboGqtEa9Q= +go.unistack.org/micro-proto/v3 v3.4.1/go.mod h1:okx/cnOhzuCX0ggl/vToatbCupi0O44diiiLLsZ93Zo= golang.org/x/net v0.14.0 h1:BONx9s002vGdD9umnlX1Po8vOZmrgH34qlHcD1MfK14= golang.org/x/net v0.14.0/go.mod h1:PpSgVXXLK0OxS0F31C1/tv6XNguvCrnXIDrFMspZIUI= golang.org/x/sync v0.3.0 h1:ftCYgMx6zT/asHUrPw8BLLscYtGznsLAnjq5RH9P66E= diff --git a/logger/logger.go b/logger/logger.go index 175311bc..20a5d01f 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -45,20 +45,27 @@ type Logger interface { // Fatal level message Fatal(ctx context.Context, args ...interface{}) // Infof level message + // DEPRECATED Infof(ctx context.Context, msg string, args ...interface{}) // Tracef level message + // DEPRECATED Tracef(ctx context.Context, msg string, args ...interface{}) - // Debug level message + // Debugf level message + // DEPRECATED Debugf(ctx context.Context, msg string, args ...interface{}) - // Warn level message + // Warnf level message + // DEPRECATED Warnf(ctx context.Context, msg string, args ...interface{}) - // Error level message + // Errorf level message + // DEPRECATED Errorf(ctx context.Context, msg string, args ...interface{}) - // Fatal level message + // Fatalf level message + // DEPRECATED Fatalf(ctx context.Context, msg string, args ...interface{}) // Log logs message with needed level Log(ctx context.Context, level Level, args ...interface{}) // Logf logs message with needed level + // DEPRECATED Logf(ctx context.Context, level Level, msg string, args ...interface{}) // Name returns broker instance name Name() string diff --git a/logger/options.go b/logger/options.go index e1113daf..1320b793 100644 --- a/logger/options.go +++ b/logger/options.go @@ -102,14 +102,14 @@ func WithOutput(out io.Writer) Option { } } -// WitAddStacktrace controls writing stacktrace on error +// WithAddStacktrace controls writing stacktrace on error func WithAddStacktrace(v bool) Option { return func(o *Options) { o.AddStacktrace = v } } -// WitAddSource controls writing source file and pos in log +// WithAddSource controls writing source file and pos in log func WithAddSource(v bool) Option { return func(o *Options) { o.AddSource = v diff --git a/logger/slog/slog.go b/logger/slog/slog.go index 76a7e1bb..57d5d7c0 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -15,6 +15,9 @@ import ( "go.unistack.org/micro/v3/tracer" ) +const badKey = "!BADKEY" +const emptyMSg = "!EMPTYMSG" + var reTrace = regexp.MustCompile(`.*/slog/logger\.go.*\n`) var ( @@ -152,22 +155,39 @@ func (s *slogLogger) Init(opts ...logger.Option) error { func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() - if !s.V(lvl) { + if !s.V(lvl) || len(attrs) == 0 { return } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), fmt.Sprintf("%s", attrs[0]), pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) + + msg := attrs[0] + attrs = prepareAttributes(attrs[1:]) + + ve, hasErr := msg.(error) + if hasErr && ve != nil { + attrs = append(attrs, slog.String(s.opts.ErrorKey, ve.Error())) } - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break + for _, fn := range s.opts.ContextAttrFuncs { + a := prepareAttributes(fn(ctx)) + attrs = append(attrs, a...) + } + + if !hasErr { + for idx, attr := range attrs { + if ve, hasErr = attr.(error); hasErr && ve != nil { + if idx%2 == 1 { + attrs = append(attrs, slog.String(s.opts.ErrorKey, ve.Error())) + } else { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + } + if span, ok := tracer.SpanFromContext(ctx); ok { + span.SetStatus(tracer.SpanStatusError, ve.Error()) + } + break + } } } + if s.opts.AddStacktrace && lvl == logger.ErrorLevel { stackInfo := make([]byte, 1024*1024) if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { @@ -177,22 +197,18 @@ func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, attrs ...interfa } } } - r.Add(attrs[1:]...) - r.Attrs(func(a slog.Attr) bool { - if a.Key == s.opts.ErrorKey { - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, a.Value.String()) - return false - } - } - return true - }) + + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), fmt.Sprintf("%s", msg), pcs[0]) + r.Add(attrs...) _ = s.handler.Handle(ctx, r) } +// Logf DEPRECATED func (s *slogLogger) Logf(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() - if !s.V(lvl) { + if !s.V(lvl) || len(attrs) == 0 { return } var pcs [1]uintptr @@ -231,30 +247,13 @@ func (s *slogLogger) Logf(ctx context.Context, lvl logger.Level, msg string, att } func (s *slogLogger) Info(ctx context.Context, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.InfoLevel.String()).Inc() - if !s.V(logger.InfoLevel) { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelInfo, fmt.Sprintf("%s", attrs[0]), pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) + s.Log(ctx, logger.InfoLevel, attrs...) } +// Infof DEPRECATED func (s *slogLogger) Infof(ctx context.Context, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.InfoLevel.String()).Inc() - if !s.V(logger.InfoLevel) { + if !s.V(logger.InfoLevel) || len(attrs) == 0 { return } var pcs [1]uintptr @@ -275,30 +274,13 @@ func (s *slogLogger) Infof(ctx context.Context, msg string, attrs ...interface{} } func (s *slogLogger) Debug(ctx context.Context, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.DebugLevel.String()).Inc() - if !s.V(logger.DebugLevel) { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug, fmt.Sprintf("%s", attrs[0]), pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) + s.Log(ctx, logger.DebugLevel, attrs...) } +// Debugf DEPRECATED func (s *slogLogger) Debugf(ctx context.Context, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.DebugLevel.String()).Inc() - if !s.V(logger.DebugLevel) { + if !s.V(logger.DebugLevel) || len(attrs) == 0 { return } var pcs [1]uintptr @@ -319,30 +301,13 @@ func (s *slogLogger) Debugf(ctx context.Context, msg string, attrs ...interface{ } func (s *slogLogger) Trace(ctx context.Context, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.TraceLevel.String()).Inc() - if !s.V(logger.TraceLevel) { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug-1, fmt.Sprintf("%s", attrs[0]), pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) + s.Log(ctx, logger.TraceLevel, attrs...) } +// Tracef DEPRECATED func (s *slogLogger) Tracef(ctx context.Context, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.TraceLevel.String()).Inc() - if !s.V(logger.TraceLevel) { + if !s.V(logger.TraceLevel) || len(attrs) == 0 { return } var pcs [1]uintptr @@ -363,48 +328,13 @@ func (s *slogLogger) Tracef(ctx context.Context, msg string, attrs ...interface{ } func (s *slogLogger) Error(ctx context.Context, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.ErrorLevel.String()).Inc() - if !s.V(logger.ErrorLevel) { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError, fmt.Sprintf("%s", attrs[0]), pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - if s.opts.AddStacktrace { - stackInfo := make([]byte, 1024*1024) - if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { - traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) - if len(traceLines) != 0 { - attrs = append(attrs, slog.String("stacktrace", traceLines[len(traceLines)-1])) - } - } - } - r.Add(attrs[1:]...) - r.Attrs(func(a slog.Attr) bool { - if a.Key == s.opts.ErrorKey { - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, a.Value.String()) - return false - } - } - return true - }) - _ = s.handler.Handle(ctx, r) + s.Log(ctx, logger.ErrorLevel, attrs...) } +// Errorf DEPRECATED func (s *slogLogger) Errorf(ctx context.Context, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.ErrorLevel.String()).Inc() - if !s.V(logger.ErrorLevel) { + if !s.V(logger.ErrorLevel) || len(attrs) == 0 { return } var pcs [1]uintptr @@ -443,31 +373,14 @@ func (s *slogLogger) Errorf(ctx context.Context, msg string, attrs ...interface{ } func (s *slogLogger) Fatal(ctx context.Context, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.FatalLevel.String()).Inc() - if !s.V(logger.FatalLevel) { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError+1, fmt.Sprintf("%s", attrs[0]), pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) + s.Log(ctx, logger.FatalLevel, attrs...) os.Exit(1) } +// Fatalf DEPRECATED func (s *slogLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.FatalLevel.String()).Inc() - if !s.V(logger.FatalLevel) { + if !s.V(logger.FatalLevel) || len(attrs) == 0 { return } var pcs [1]uintptr @@ -489,30 +402,13 @@ func (s *slogLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{ } func (s *slogLogger) Warn(ctx context.Context, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.WarnLevel.String()).Inc() - if !s.V(logger.WarnLevel) { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelWarn, fmt.Sprintf("%s", attrs[0]), pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) + s.Log(ctx, logger.WarnLevel, attrs...) } +// Warnf DEPRECATED func (s *slogLogger) Warnf(ctx context.Context, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.WarnLevel.String()).Inc() - if !s.V(logger.WarnLevel) { + if !s.V(logger.WarnLevel) || len(attrs) == 0 { return } var pcs [1]uintptr @@ -581,3 +477,13 @@ func slogToLoggerLevel(level slog.Level) logger.Level { return logger.InfoLevel } } + +func prepareAttributes(attrs []interface{}) []interface{} { + + if len(attrs)%2 == 1 { + attrs = append(attrs, badKey) + attrs[len(attrs)-1], attrs[len(attrs)-2] = attrs[len(attrs)-2], attrs[len(attrs)-1] + } + + return attrs +} diff --git a/logger/slog/slog_test.go b/logger/slog/slog_test.go index 93c63c79..9dc34e29 100644 --- a/logger/slog/slog_test.go +++ b/logger/slog/slog_test.go @@ -3,6 +3,7 @@ package slog import ( "bytes" "context" + "errors" "fmt" "log" "testing" @@ -29,13 +30,25 @@ func TestError(t *testing.T) { func TestErrorf(t *testing.T) { ctx := context.TODO() + buf := bytes.NewBuffer(nil) l := NewLogger(logger.WithLevel(logger.ErrorLevel), logger.WithOutput(buf), logger.WithAddStacktrace(true)) - if err := l.Init(); err != nil { + if err := l.Init(logger.WithContextAttrFuncs(func(ctx context.Context) []interface{} { + return nil + })); err != nil { t.Fatal(err) } - l.Errorf(ctx, "message", fmt.Errorf("error message")) + l.Log(ctx, logger.ErrorLevel, "message", errors.New("error msg")) + if !bytes.Contains(buf.Bytes(), []byte(`"!BADKEY":"`)) { + t.Fatalf("logger BADKEY not works, buf contains: %s", buf.Bytes()) + } + + l.Log(ctx, logger.ErrorLevel, errors.New("error msg")) + if !bytes.Contains(buf.Bytes(), []byte(`"error":"error msg"`)) { + t.Fatalf("logger error not works, buf contains: %s", buf.Bytes()) + } + if !bytes.Contains(buf.Bytes(), []byte(`"stacktrace":"`)) { t.Fatalf("logger stacktrace not works, buf contains: %s", buf.Bytes()) } @@ -99,6 +112,11 @@ func TestFromContextWithFields(t *testing.T) { if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) { t.Fatalf("logger fields not works, buf contains: %s", buf.Bytes()) } + + l.Info(ctx, "test", "uncorrected number attributes") + if !bytes.Contains(buf.Bytes(), []byte(`"!BADKEY":"uncorrected number attributes"`)) { + t.Fatalf("logger fields not works, buf contains: %s", buf.Bytes()) + } } func TestClone(t *testing.T) { -- 2.45.2 From ed6d57c0dd5024521b954eddf4ea366083963aef Mon Sep 17 00:00:00 2001 From: Evstigneev Denis Date: Wed, 9 Oct 2024 20:32:54 +0300 Subject: [PATCH 02/10] move to new method && add to CallerSkiper --- logger/logger.go | 2 +- logger/slog/slog.go | 466 ++++++++++++++++++++++---------------------- 2 files changed, 236 insertions(+), 232 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 20a5d01f..325628ac 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -15,7 +15,7 @@ var ( // DefaultLevel used by logger DefaultLevel = InfoLevel // DefaultCallerSkipCount used by logger - DefaultCallerSkipCount = 2 + DefaultCallerSkipCount = 3 ) // Logger is a generic logging interface diff --git a/logger/slog/slog.go b/logger/slog/slog.go index 57d5d7c0..a723deb9 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -154,6 +154,241 @@ func (s *slogLogger) Init(opts ...logger.Option) error { } func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, attrs ...interface{}) { + s.printLog(ctx, lvl, attrs...) +} + +// Logf DEPRECATED +func (s *slogLogger) Logf(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() + if !s.V(lvl) || len(attrs) == 0 { + return + } + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), msg, pcs[0]) + for _, fn := range s.opts.ContextAttrFuncs { + attrs = append(attrs, fn(ctx)...) + } + + for idx, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + break + } + } + if s.opts.AddStacktrace && lvl == logger.ErrorLevel { + stackInfo := make([]byte, 1024*1024) + if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { + traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) + if len(traceLines) != 0 { + attrs = append(attrs, (slog.String(s.opts.StacktraceKey, traceLines[len(traceLines)-1]))) + } + } + } + r.Add(attrs[1:]...) + r.Attrs(func(a slog.Attr) bool { + if a.Key == s.opts.ErrorKey { + if span, ok := tracer.SpanFromContext(ctx); ok { + span.SetStatus(tracer.SpanStatusError, a.Value.String()) + return false + } + } + return true + }) + _ = s.handler.Handle(ctx, r) +} + +func (s *slogLogger) Info(ctx context.Context, attrs ...interface{}) { + s.printLog(ctx, logger.InfoLevel, attrs...) +} + +// Infof DEPRECATED +func (s *slogLogger) Infof(ctx context.Context, msg string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.InfoLevel.String()).Inc() + if !s.V(logger.InfoLevel) || len(attrs) == 0 { + return + } + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelInfo, msg, pcs[0]) + for _, fn := range s.opts.ContextAttrFuncs { + attrs = append(attrs, fn(ctx)...) + } + + for idx, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + break + } + } + r.Add(attrs...) + _ = s.handler.Handle(ctx, r) +} + +func (s *slogLogger) Debug(ctx context.Context, attrs ...interface{}) { + s.printLog(ctx, logger.DebugLevel, attrs...) +} + +// Debugf DEPRECATED +func (s *slogLogger) Debugf(ctx context.Context, msg string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.DebugLevel.String()).Inc() + if !s.V(logger.DebugLevel) || len(attrs) == 0 { + return + } + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug, msg, pcs[0]) + for _, fn := range s.opts.ContextAttrFuncs { + attrs = append(attrs, fn(ctx)...) + } + + for idx, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + break + } + } + r.Add(attrs...) + _ = s.handler.Handle(ctx, r) +} + +func (s *slogLogger) Trace(ctx context.Context, attrs ...interface{}) { + s.printLog(ctx, logger.TraceLevel, attrs...) +} + +// Tracef DEPRECATED +func (s *slogLogger) Tracef(ctx context.Context, msg string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.TraceLevel.String()).Inc() + if !s.V(logger.TraceLevel) || len(attrs) == 0 { + return + } + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug-1, msg, pcs[0]) + for _, fn := range s.opts.ContextAttrFuncs { + attrs = append(attrs, fn(ctx)...) + } + + for idx, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + break + } + } + r.Add(attrs[1:]...) + _ = s.handler.Handle(ctx, r) +} + +func (s *slogLogger) Error(ctx context.Context, attrs ...interface{}) { + s.printLog(ctx, logger.ErrorLevel, attrs...) +} + +// Errorf DEPRECATED +func (s *slogLogger) Errorf(ctx context.Context, msg string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.ErrorLevel.String()).Inc() + if !s.V(logger.ErrorLevel) || len(attrs) == 0 { + return + } + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError, msg, pcs[0]) + for _, fn := range s.opts.ContextAttrFuncs { + attrs = append(attrs, fn(ctx)...) + } + + for idx, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + break + } + } + if s.opts.AddStacktrace { + stackInfo := make([]byte, 1024*1024) + if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { + traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) + if len(traceLines) != 0 { + attrs = append(attrs, slog.String("stacktrace", traceLines[len(traceLines)-1])) + } + } + } + r.Add(attrs...) + r.Attrs(func(a slog.Attr) bool { + if a.Key == s.opts.ErrorKey { + if span, ok := tracer.SpanFromContext(ctx); ok { + span.SetStatus(tracer.SpanStatusError, a.Value.String()) + return false + } + } + return true + }) + _ = s.handler.Handle(ctx, r) +} + +func (s *slogLogger) Fatal(ctx context.Context, attrs ...interface{}) { + s.printLog(ctx, logger.FatalLevel, attrs...) + os.Exit(1) +} + +// Fatalf DEPRECATED +func (s *slogLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.FatalLevel.String()).Inc() + if !s.V(logger.FatalLevel) || len(attrs) == 0 { + return + } + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError+1, msg, pcs[0]) + for _, fn := range s.opts.ContextAttrFuncs { + attrs = append(attrs, fn(ctx)...) + } + + for idx, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + break + } + } + r.Add(attrs...) + _ = s.handler.Handle(ctx, r) + os.Exit(1) +} + +func (s *slogLogger) Warn(ctx context.Context, attrs ...interface{}) { + s.printLog(ctx, logger.WarnLevel, attrs...) +} + +// Warnf DEPRECATED +func (s *slogLogger) Warnf(ctx context.Context, msg string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.WarnLevel.String()).Inc() + if !s.V(logger.WarnLevel) || len(attrs) == 0 { + return + } + var pcs [1]uintptr + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelWarn, msg, pcs[0]) + for _, fn := range s.opts.ContextAttrFuncs { + attrs = append(attrs, fn(ctx)...) + } + + for idx, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) + break + } + } + r.Add(attrs[1:]...) + _ = s.handler.Handle(ctx, r) +} + +func (s *slogLogger) Name() string { + return s.opts.Name +} + +func (s *slogLogger) String() string { + return "slog" +} + +func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() if !s.V(lvl) || len(attrs) == 0 { return @@ -205,237 +440,6 @@ func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, attrs ...interfa _ = s.handler.Handle(ctx, r) } -// Logf DEPRECATED -func (s *slogLogger) Logf(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() - if !s.V(lvl) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - if s.opts.AddStacktrace && lvl == logger.ErrorLevel { - stackInfo := make([]byte, 1024*1024) - if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { - traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) - if len(traceLines) != 0 { - attrs = append(attrs, (slog.String(s.opts.StacktraceKey, traceLines[len(traceLines)-1]))) - } - } - } - r.Add(attrs[1:]...) - r.Attrs(func(a slog.Attr) bool { - if a.Key == s.opts.ErrorKey { - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, a.Value.String()) - return false - } - } - return true - }) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Info(ctx context.Context, attrs ...interface{}) { - s.Log(ctx, logger.InfoLevel, attrs...) -} - -// Infof DEPRECATED -func (s *slogLogger) Infof(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.InfoLevel.String()).Inc() - if !s.V(logger.InfoLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelInfo, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs...) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Debug(ctx context.Context, attrs ...interface{}) { - s.Log(ctx, logger.DebugLevel, attrs...) -} - -// Debugf DEPRECATED -func (s *slogLogger) Debugf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.DebugLevel.String()).Inc() - if !s.V(logger.DebugLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs...) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Trace(ctx context.Context, attrs ...interface{}) { - s.Log(ctx, logger.TraceLevel, attrs...) -} - -// Tracef DEPRECATED -func (s *slogLogger) Tracef(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.TraceLevel.String()).Inc() - if !s.V(logger.TraceLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug-1, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Error(ctx context.Context, attrs ...interface{}) { - s.Log(ctx, logger.ErrorLevel, attrs...) -} - -// Errorf DEPRECATED -func (s *slogLogger) Errorf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.ErrorLevel.String()).Inc() - if !s.V(logger.ErrorLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - if s.opts.AddStacktrace { - stackInfo := make([]byte, 1024*1024) - if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { - traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) - if len(traceLines) != 0 { - attrs = append(attrs, slog.String("stacktrace", traceLines[len(traceLines)-1])) - } - } - } - r.Add(attrs...) - r.Attrs(func(a slog.Attr) bool { - if a.Key == s.opts.ErrorKey { - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, a.Value.String()) - return false - } - } - return true - }) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Fatal(ctx context.Context, attrs ...interface{}) { - s.Log(ctx, logger.FatalLevel, attrs...) - os.Exit(1) -} - -// Fatalf DEPRECATED -func (s *slogLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.FatalLevel.String()).Inc() - if !s.V(logger.FatalLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError+1, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs...) - _ = s.handler.Handle(ctx, r) - os.Exit(1) -} - -func (s *slogLogger) Warn(ctx context.Context, attrs ...interface{}) { - s.Log(ctx, logger.WarnLevel, attrs...) -} - -// Warnf DEPRECATED -func (s *slogLogger) Warnf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.WarnLevel.String()).Inc() - if !s.V(logger.WarnLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelWarn, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Name() string { - return s.opts.Name -} - -func (s *slogLogger) String() string { - return "slog" -} - func NewLogger(opts ...logger.Option) logger.Logger { s := &slogLogger{ opts: logger.NewOptions(opts...), -- 2.45.2 From bc9102c73a15f3a87d32993ffed1c1c83f95ef55 Mon Sep 17 00:00:00 2001 From: Evstigneev Denis Date: Wed, 9 Oct 2024 20:50:53 +0300 Subject: [PATCH 03/10] add test with contextAttrFunc --- logger/slog/slog_test.go | 46 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 46 insertions(+) diff --git a/logger/slog/slog_test.go b/logger/slog/slog_test.go index 9dc34e29..8f94d663 100644 --- a/logger/slog/slog_test.go +++ b/logger/slog/slog_test.go @@ -5,7 +5,10 @@ import ( "context" "errors" "fmt" + "github.com/google/uuid" + "go.unistack.org/micro/v3/metadata" "log" + "strings" "testing" "go.unistack.org/micro/v3/logger" @@ -192,3 +195,46 @@ func TestLogger(t *testing.T) { t.Fatalf("logger warn, buf %s", buf.Bytes()) } } + +func Test_WithContextAttrFunc(t *testing.T) { + loggerContextAttrFuncs := []logger.ContextAttrFunc{ + func(ctx context.Context) []interface{} { + md, ok := metadata.FromIncomingContext(ctx) + if !ok { + return nil + } + attrs := make([]interface{}, 0, 10) + for k, v := range md { + switch k { + case "X-Request-Id", "Phone", "External-Id", "Source-Service", "X-App-Install-Id", "Client-Id", "Client-Ip": + attrs = append(attrs, strings.ToLower(k), v) + } + } + return attrs + }, + } + + logger.DefaultContextAttrFuncs = append(logger.DefaultContextAttrFuncs, loggerContextAttrFuncs...) + + ctx := context.TODO() + ctx = metadata.AppendIncomingContext(ctx, "X-Request-Id", uuid.New().String(), + "Source-Service", "Test-System") + + buf := bytes.NewBuffer(nil) + l := NewLogger(logger.WithLevel(logger.TraceLevel), logger.WithOutput(buf)) + if err := l.Init(); err != nil { + t.Fatal(err) + } + + l.Info(ctx, "test message") + if !(bytes.Contains(buf.Bytes(), []byte(`"level":"info"`)) && bytes.Contains(buf.Bytes(), []byte(`"msg":"test message"`))) { + t.Fatalf("logger info, buf %s", buf.Bytes()) + } + if !(bytes.Contains(buf.Bytes(), []byte(`"x-request-id":"`))) { + t.Fatalf("logger info, buf %s", buf.Bytes()) + } + if !(bytes.Contains(buf.Bytes(), []byte(`"source-service":"Test-System"`))) { + t.Fatalf("logger info, buf %s", buf.Bytes()) + } + +} -- 2.45.2 From c1e3e9c5a26f19607d1e334b42b04f159ead704c Mon Sep 17 00:00:00 2001 From: Evstigneev Denis Date: Wed, 9 Oct 2024 21:16:43 +0300 Subject: [PATCH 04/10] add unpack labels --- logger/wrapper/wrapper.go | 52 +++++++++++++++++++++++++-------------- 1 file changed, 34 insertions(+), 18 deletions(-) diff --git a/logger/wrapper/wrapper.go b/logger/wrapper/wrapper.go index ee96f5c6..52126261 100644 --- a/logger/wrapper/wrapper.go +++ b/logger/wrapper/wrapper.go @@ -224,11 +224,12 @@ func (l *lWrapper) Call(ctx context.Context, req client.Request, rsp interface{} return err } - var labels []string + var labels []interface{} for _, o := range l.opts.ClientCallObservers { - labels = append(labels, o(ctx, req, rsp, opts, err)...) + attrs := convertToInterface(o(ctx, req, rsp, opts, err)) + labels = append(labels, attrs...) } - l.opts.Logger.Fields(labels).Log(ctx, l.opts.Level) + l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) return err } @@ -247,11 +248,12 @@ func (l *lWrapper) Stream(ctx context.Context, req client.Request, opts ...clien return stream, err } - var labels []string + var labels []interface{} for _, o := range l.opts.ClientStreamObservers { - labels = append(labels, o(ctx, req, opts, stream, err)...) + attrs := convertToInterface(o(ctx, req, opts, stream, err)) + labels = append(labels, attrs...) } - l.opts.Logger.Fields(labels).Log(ctx, l.opts.Level) + l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) return stream, err } @@ -270,11 +272,12 @@ func (l *lWrapper) Publish(ctx context.Context, msg client.Message, opts ...clie return err } - var labels []string + var labels []interface{} for _, o := range l.opts.ClientPublishObservers { - labels = append(labels, o(ctx, msg, opts, err)...) + attrs := convertToInterface(o(ctx, msg, opts, err)) + labels = append(labels, attrs...) } - l.opts.Logger.Fields(labels).Log(ctx, l.opts.Level) + l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) return err } @@ -293,11 +296,12 @@ func (l *lWrapper) ServerHandler(ctx context.Context, req server.Request, rsp in return err } - var labels []string + var labels []interface{} for _, o := range l.opts.ServerHandlerObservers { - labels = append(labels, o(ctx, req, rsp, err)...) + attrs := convertToInterface(o(ctx, req, rsp, err)) + labels = append(labels, attrs...) } - l.opts.Logger.Fields(labels).Log(ctx, l.opts.Level) + l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) return err } @@ -316,11 +320,12 @@ func (l *lWrapper) ServerSubscriber(ctx context.Context, msg server.Message) err return err } - var labels []string + var labels []interface{} for _, o := range l.opts.ServerSubscriberObservers { - labels = append(labels, o(ctx, msg, err)...) + attrs := convertToInterface(o(ctx, msg, err)) + labels = append(labels, attrs...) } - l.opts.Logger.Fields(labels).Log(ctx, l.opts.Level) + l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) return err } @@ -363,11 +368,12 @@ func (l *lWrapper) ClientCallFunc(ctx context.Context, addr string, req client.R return err } - var labels []string + var labels []interface{} for _, o := range l.opts.ClientCallFuncObservers { - labels = append(labels, o(ctx, addr, req, rsp, opts, err)...) + attrs := convertToInterface(o(ctx, addr, req, rsp, opts, err)) + labels = append(labels, attrs...) } - l.opts.Logger.Fields(labels).Log(ctx, l.opts.Level) + l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) return err } @@ -397,3 +403,13 @@ func NewServerSubscriberWrapper(opts ...Option) server.SubscriberWrapper { return l.ServerSubscriber } } + +func convertToInterface(attrs []string) []interface{} { + result := make([]interface{}, 0, len(attrs)) + + for idx := range attrs { + result = append(result, attrs[idx]) + } + + return result +} -- 2.45.2 From 3d406bfb2256662ffa044ddc7eeb9db2d1cda8e8 Mon Sep 17 00:00:00 2001 From: devstigneev Date: Thu, 10 Oct 2024 17:56:20 +0300 Subject: [PATCH 05/10] deleted log/wrappers and add spanErr --- logger/slog/slog.go | 3 + logger/wrapper/wrapper.go | 415 -------------------------------------- 2 files changed, 3 insertions(+), 415 deletions(-) delete mode 100644 logger/wrapper/wrapper.go diff --git a/logger/slog/slog.go b/logger/slog/slog.go index a723deb9..b2a1e8f3 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -400,6 +400,9 @@ func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, attrs ...in ve, hasErr := msg.(error) if hasErr && ve != nil { attrs = append(attrs, slog.String(s.opts.ErrorKey, ve.Error())) + if span, ok := tracer.SpanFromContext(ctx); ok { + span.SetStatus(tracer.SpanStatusError, ve.Error()) + } } for _, fn := range s.opts.ContextAttrFuncs { diff --git a/logger/wrapper/wrapper.go b/logger/wrapper/wrapper.go deleted file mode 100644 index 52126261..00000000 --- a/logger/wrapper/wrapper.go +++ /dev/null @@ -1,415 +0,0 @@ -// Package wrapper provides wrapper for Logger -package wrapper - -import ( - "context" - "fmt" - - "go.unistack.org/micro/v3/client" - "go.unistack.org/micro/v3/logger" - "go.unistack.org/micro/v3/server" -) - -var ( - // DefaultClientCallObserver called by wrapper in client Call - DefaultClientCallObserver = func(ctx context.Context, req client.Request, rsp interface{}, opts []client.CallOption, err error) []string { - labels := []string{"service", req.Service(), "endpoint", req.Endpoint()} - if err != nil { - labels = append(labels, "error", err.Error()) - } - return labels - } - - // DefaultClientStreamObserver called by wrapper in client Stream - DefaultClientStreamObserver = func(ctx context.Context, req client.Request, opts []client.CallOption, stream client.Stream, err error) []string { - labels := []string{"service", req.Service(), "endpoint", req.Endpoint()} - if err != nil { - labels = append(labels, "error", err.Error()) - } - return labels - } - - // DefaultClientPublishObserver called by wrapper in client Publish - DefaultClientPublishObserver = func(ctx context.Context, msg client.Message, opts []client.PublishOption, err error) []string { - labels := []string{"endpoint", msg.Topic()} - if err != nil { - labels = append(labels, "error", err.Error()) - } - return labels - } - - // DefaultServerHandlerObserver called by wrapper in server Handler - DefaultServerHandlerObserver = func(ctx context.Context, req server.Request, rsp interface{}, err error) []string { - labels := []string{"service", req.Service(), "endpoint", req.Endpoint()} - if err != nil { - labels = append(labels, "error", err.Error()) - } - return labels - } - - // DefaultServerSubscriberObserver called by wrapper in server Subscriber - DefaultServerSubscriberObserver = func(ctx context.Context, msg server.Message, err error) []string { - labels := []string{"endpoint", msg.Topic()} - if err != nil { - labels = append(labels, "error", err.Error()) - } - return labels - } - - // DefaultClientCallFuncObserver called by wrapper in client CallFunc - DefaultClientCallFuncObserver = func(ctx context.Context, addr string, req client.Request, rsp interface{}, opts client.CallOptions, err error) []string { - labels := []string{"service", req.Service(), "endpoint", req.Endpoint()} - if err != nil { - labels = append(labels, "error", err.Error()) - } - return labels - } - - // DefaultSkipEndpoints wrapper not called for this endpoints - DefaultSkipEndpoints = []string{"Meter.Metrics", "Health.Live", "Health.Ready", "Health.Version"} -) - -type lWrapper struct { - client.Client - serverHandler server.HandlerFunc - serverSubscriber server.SubscriberFunc - clientCallFunc client.CallFunc - opts Options -} - -type ( - // ClientCallObserver func signature - ClientCallObserver func(context.Context, client.Request, interface{}, []client.CallOption, error) []string - // ClientStreamObserver func signature - ClientStreamObserver func(context.Context, client.Request, []client.CallOption, client.Stream, error) []string - // ClientPublishObserver func signature - ClientPublishObserver func(context.Context, client.Message, []client.PublishOption, error) []string - // ClientCallFuncObserver func signature - ClientCallFuncObserver func(context.Context, string, client.Request, interface{}, client.CallOptions, error) []string - // ServerHandlerObserver func signature - ServerHandlerObserver func(context.Context, server.Request, interface{}, error) []string - // ServerSubscriberObserver func signature - ServerSubscriberObserver func(context.Context, server.Message, error) []string -) - -// Options struct for wrapper -type Options struct { - // Logger that used for log - Logger logger.Logger - // ServerHandlerObservers funcs - ServerHandlerObservers []ServerHandlerObserver - // ServerSubscriberObservers funcs - ServerSubscriberObservers []ServerSubscriberObserver - // ClientCallObservers funcs - ClientCallObservers []ClientCallObserver - // ClientStreamObservers funcs - ClientStreamObservers []ClientStreamObserver - // ClientPublishObservers funcs - ClientPublishObservers []ClientPublishObserver - // ClientCallFuncObservers funcs - ClientCallFuncObservers []ClientCallFuncObserver - // SkipEndpoints - SkipEndpoints []string - // Level for logger - Level logger.Level - // Enabled flag - Enabled bool -} - -// Option func signature -type Option func(*Options) - -// NewOptions creates Options from Option slice -func NewOptions(opts ...Option) Options { - options := Options{ - Logger: logger.DefaultLogger, - Level: logger.TraceLevel, - ClientCallObservers: []ClientCallObserver{DefaultClientCallObserver}, - ClientStreamObservers: []ClientStreamObserver{DefaultClientStreamObserver}, - ClientPublishObservers: []ClientPublishObserver{DefaultClientPublishObserver}, - ClientCallFuncObservers: []ClientCallFuncObserver{DefaultClientCallFuncObserver}, - ServerHandlerObservers: []ServerHandlerObserver{DefaultServerHandlerObserver}, - ServerSubscriberObservers: []ServerSubscriberObserver{DefaultServerSubscriberObserver}, - SkipEndpoints: DefaultSkipEndpoints, - } - - for _, o := range opts { - o(&options) - } - - return options -} - -// WithEnabled enable/diable flag -func WithEnabled(b bool) Option { - return func(o *Options) { - o.Enabled = b - } -} - -// WithLevel log level -func WithLevel(l logger.Level) Option { - return func(o *Options) { - o.Level = l - } -} - -// WithLogger logger -func WithLogger(l logger.Logger) Option { - return func(o *Options) { - o.Logger = l - } -} - -// WithClientCallObservers funcs -func WithClientCallObservers(ob ...ClientCallObserver) Option { - return func(o *Options) { - o.ClientCallObservers = ob - } -} - -// WithClientStreamObservers funcs -func WithClientStreamObservers(ob ...ClientStreamObserver) Option { - return func(o *Options) { - o.ClientStreamObservers = ob - } -} - -// WithClientPublishObservers funcs -func WithClientPublishObservers(ob ...ClientPublishObserver) Option { - return func(o *Options) { - o.ClientPublishObservers = ob - } -} - -// WithClientCallFuncObservers funcs -func WithClientCallFuncObservers(ob ...ClientCallFuncObserver) Option { - return func(o *Options) { - o.ClientCallFuncObservers = ob - } -} - -// WithServerHandlerObservers funcs -func WithServerHandlerObservers(ob ...ServerHandlerObserver) Option { - return func(o *Options) { - o.ServerHandlerObservers = ob - } -} - -// WithServerSubscriberObservers funcs -func WithServerSubscriberObservers(ob ...ServerSubscriberObserver) Option { - return func(o *Options) { - o.ServerSubscriberObservers = ob - } -} - -// SkipEndpoins -func SkipEndpoints(eps ...string) Option { - return func(o *Options) { - o.SkipEndpoints = append(o.SkipEndpoints, eps...) - } -} - -func (l *lWrapper) Call(ctx context.Context, req client.Request, rsp interface{}, opts ...client.CallOption) error { - err := l.Client.Call(ctx, req, rsp, opts...) - - endpoint := fmt.Sprintf("%s.%s", req.Service(), req.Endpoint()) - for _, ep := range l.opts.SkipEndpoints { - if ep == endpoint { - return err - } - } - - if !l.opts.Enabled { - return err - } - - var labels []interface{} - for _, o := range l.opts.ClientCallObservers { - attrs := convertToInterface(o(ctx, req, rsp, opts, err)) - labels = append(labels, attrs...) - } - l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) - - return err -} - -func (l *lWrapper) Stream(ctx context.Context, req client.Request, opts ...client.CallOption) (client.Stream, error) { - stream, err := l.Client.Stream(ctx, req, opts...) - - endpoint := fmt.Sprintf("%s.%s", req.Service(), req.Endpoint()) - for _, ep := range l.opts.SkipEndpoints { - if ep == endpoint { - return stream, err - } - } - - if !l.opts.Enabled { - return stream, err - } - - var labels []interface{} - for _, o := range l.opts.ClientStreamObservers { - attrs := convertToInterface(o(ctx, req, opts, stream, err)) - labels = append(labels, attrs...) - } - l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) - - return stream, err -} - -func (l *lWrapper) Publish(ctx context.Context, msg client.Message, opts ...client.PublishOption) error { - err := l.Client.Publish(ctx, msg, opts...) - - endpoint := msg.Topic() - for _, ep := range l.opts.SkipEndpoints { - if ep == endpoint { - return err - } - } - - if !l.opts.Enabled { - return err - } - - var labels []interface{} - for _, o := range l.opts.ClientPublishObservers { - attrs := convertToInterface(o(ctx, msg, opts, err)) - labels = append(labels, attrs...) - } - l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) - - return err -} - -func (l *lWrapper) ServerHandler(ctx context.Context, req server.Request, rsp interface{}) error { - err := l.serverHandler(ctx, req, rsp) - - endpoint := req.Endpoint() - for _, ep := range l.opts.SkipEndpoints { - if ep == endpoint { - return err - } - } - - if !l.opts.Enabled { - return err - } - - var labels []interface{} - for _, o := range l.opts.ServerHandlerObservers { - attrs := convertToInterface(o(ctx, req, rsp, err)) - labels = append(labels, attrs...) - } - l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) - - return err -} - -func (l *lWrapper) ServerSubscriber(ctx context.Context, msg server.Message) error { - err := l.serverSubscriber(ctx, msg) - - endpoint := msg.Topic() - for _, ep := range l.opts.SkipEndpoints { - if ep == endpoint { - return err - } - } - - if !l.opts.Enabled { - return err - } - - var labels []interface{} - for _, o := range l.opts.ServerSubscriberObservers { - attrs := convertToInterface(o(ctx, msg, err)) - labels = append(labels, attrs...) - } - l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) - - return err -} - -// NewClientWrapper accepts an open options and returns a Client Wrapper -func NewClientWrapper(opts ...Option) client.Wrapper { - return func(c client.Client) client.Client { - options := NewOptions() - for _, o := range opts { - o(&options) - } - return &lWrapper{opts: options, Client: c} - } -} - -// NewClientCallWrapper accepts an options and returns a Call Wrapper -func NewClientCallWrapper(opts ...Option) client.CallWrapper { - return func(h client.CallFunc) client.CallFunc { - options := NewOptions() - for _, o := range opts { - o(&options) - } - - l := &lWrapper{opts: options, clientCallFunc: h} - return l.ClientCallFunc - } -} - -func (l *lWrapper) ClientCallFunc(ctx context.Context, addr string, req client.Request, rsp interface{}, opts client.CallOptions) error { - err := l.clientCallFunc(ctx, addr, req, rsp, opts) - - endpoint := fmt.Sprintf("%s.%s", req.Service(), req.Endpoint()) - for _, ep := range l.opts.SkipEndpoints { - if ep == endpoint { - return err - } - } - - if !l.opts.Enabled { - return err - } - - var labels []interface{} - for _, o := range l.opts.ClientCallFuncObservers { - attrs := convertToInterface(o(ctx, addr, req, rsp, opts, err)) - labels = append(labels, attrs...) - } - l.opts.Logger.Fields(labels...).Log(ctx, l.opts.Level) - - return err -} - -// NewServerHandlerWrapper accepts an options and returns a Handler Wrapper -func NewServerHandlerWrapper(opts ...Option) server.HandlerWrapper { - return func(h server.HandlerFunc) server.HandlerFunc { - options := NewOptions() - for _, o := range opts { - o(&options) - } - - l := &lWrapper{opts: options, serverHandler: h} - return l.ServerHandler - } -} - -// NewServerSubscriberWrapper accepts an options and returns a Subscriber Wrapper -func NewServerSubscriberWrapper(opts ...Option) server.SubscriberWrapper { - return func(h server.SubscriberFunc) server.SubscriberFunc { - options := NewOptions() - for _, o := range opts { - o(&options) - } - - l := &lWrapper{opts: options, serverSubscriber: h} - return l.ServerSubscriber - } -} - -func convertToInterface(attrs []string) []interface{} { - result := make([]interface{}, 0, len(attrs)) - - for idx := range attrs { - result = append(result, attrs[idx]) - } - - return result -} -- 2.45.2 From 69b44047396f34142e77d6aedd75535c526dc638 Mon Sep 17 00:00:00 2001 From: Evstigneev Denis Date: Fri, 11 Oct 2024 09:06:40 +0300 Subject: [PATCH 06/10] removed skipCallers --- logger/logger.go | 2 -- logger/options.go | 17 ----------------- logger/slog/slog.go | 22 +++++++++++++--------- 3 files changed, 13 insertions(+), 28 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 325628ac..aac0734c 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -14,8 +14,6 @@ var ( DefaultLogger Logger = NewLogger() // DefaultLevel used by logger DefaultLevel = InfoLevel - // DefaultCallerSkipCount used by logger - DefaultCallerSkipCount = 3 ) // Logger is a generic logging interface diff --git a/logger/options.go b/logger/options.go index 1320b793..bcf31142 100644 --- a/logger/options.go +++ b/logger/options.go @@ -23,8 +23,6 @@ type Options struct { Name string // Fields holds additional metadata Fields []interface{} - // CallerSkipCount number of frmaes to skip - CallerSkipCount int // ContextAttrFuncs contains funcs that executed before log func on context ContextAttrFuncs []ContextAttrFunc // TimeKey is the key used for the time of the log call @@ -57,7 +55,6 @@ func NewOptions(opts ...Option) Options { Level: DefaultLevel, Fields: make([]interface{}, 0, 6), Out: os.Stderr, - CallerSkipCount: DefaultCallerSkipCount, Context: context.Background(), ContextAttrFuncs: DefaultContextAttrFuncs, AddSource: true, @@ -116,13 +113,6 @@ func WithAddSource(v bool) Option { } } -// WithCallerSkipCount set frame count to skip -func WithCallerSkipCount(c int) Option { - return func(o *Options) { - o.CallerSkipCount = c - } -} - // WithContext set context func WithContext(ctx context.Context) Option { return func(o *Options) { @@ -194,10 +184,3 @@ func WithMicroKeys() Option { o.ErrorKey = "error" } } - -// WithAddCallerSkipCount add skip count for copy logger -func WithAddCallerSkipCount(n int) Option { - return func(o *Options) { - o.CallerSkipCount += n - } -} diff --git a/logger/slog/slog.go b/logger/slog/slog.go index b2a1e8f3..d90daafd 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -15,7 +15,11 @@ import ( "go.unistack.org/micro/v3/tracer" ) -const badKey = "!BADKEY" +const ( + badKey = "!BADKEY" + // DefaultCallerSkipCount used by logger + defaultCallerSkipCount = 3 +) const emptyMSg = "!EMPTYMSG" var reTrace = regexp.MustCompile(`.*/slog/logger\.go.*\n`) @@ -164,7 +168,7 @@ func (s *slogLogger) Logf(ctx context.Context, lvl logger.Level, msg string, att return } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(2, pcs[:]) // skip [Callers, Logf] r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), msg, pcs[0]) for _, fn := range s.opts.ContextAttrFuncs { attrs = append(attrs, fn(ctx)...) @@ -209,7 +213,7 @@ func (s *slogLogger) Infof(ctx context.Context, msg string, attrs ...interface{} return } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(2, pcs[:]) // skip [Callers, Infof] r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelInfo, msg, pcs[0]) for _, fn := range s.opts.ContextAttrFuncs { attrs = append(attrs, fn(ctx)...) @@ -236,7 +240,7 @@ func (s *slogLogger) Debugf(ctx context.Context, msg string, attrs ...interface{ return } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(2, pcs[:]) // skip [Callers, Debugf] r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug, msg, pcs[0]) for _, fn := range s.opts.ContextAttrFuncs { attrs = append(attrs, fn(ctx)...) @@ -263,7 +267,7 @@ func (s *slogLogger) Tracef(ctx context.Context, msg string, attrs ...interface{ return } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(2, pcs[:]) // skip [Callers, Tracef] r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug-1, msg, pcs[0]) for _, fn := range s.opts.ContextAttrFuncs { attrs = append(attrs, fn(ctx)...) @@ -290,7 +294,7 @@ func (s *slogLogger) Errorf(ctx context.Context, msg string, attrs ...interface{ return } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(2, pcs[:]) // skip [Callers, Errorf] r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError, msg, pcs[0]) for _, fn := range s.opts.ContextAttrFuncs { attrs = append(attrs, fn(ctx)...) @@ -336,7 +340,7 @@ func (s *slogLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{ return } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(2, pcs[:]) // skip [Callers, Fatalf] r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError+1, msg, pcs[0]) for _, fn := range s.opts.ContextAttrFuncs { attrs = append(attrs, fn(ctx)...) @@ -364,7 +368,7 @@ func (s *slogLogger) Warnf(ctx context.Context, msg string, attrs ...interface{} return } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(2, pcs[:]) // skip [Callers, Warnf] r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelWarn, msg, pcs[0]) for _, fn := range s.opts.ContextAttrFuncs { attrs = append(attrs, fn(ctx)...) @@ -437,7 +441,7 @@ func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, attrs ...in } var pcs [1]uintptr - runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof] + runtime.Callers(defaultCallerSkipCount, pcs[:]) // skip [Callers, printLog, LogLvlMethod] r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), fmt.Sprintf("%s", msg), pcs[0]) r.Add(attrs...) _ = s.handler.Handle(ctx, r) -- 2.45.2 From 0bb2a2f0dcae8a026bc3c3a6cd37dfd72f600745 Mon Sep 17 00:00:00 2001 From: Evstigneev Denis Date: Fri, 11 Oct 2024 09:56:07 +0300 Subject: [PATCH 07/10] add printlogf --- logger/slog/slog.go | 56 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 56 insertions(+) diff --git a/logger/slog/slog.go b/logger/slog/slog.go index d90daafd..b2260a58 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -447,6 +447,62 @@ func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, attrs ...in _ = s.handler.Handle(ctx, r) } +func (s *slogLogger) printLogf(ctx context.Context, lvl logger.Level, format string, attrs ...interface{}) { + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() + if !s.V(lvl) { + return + } + + msg := fmt.Sprintf(format, attrs...) + + var nAttrs []interface{} + for _, fn := range s.opts.ContextAttrFuncs { + a := prepareAttributes(fn(ctx)) + nAttrs = append(nAttrs, a...) + } + + hasErr := false + for _, attr := range attrs { + if ve, ok := attr.(error); ok && ve != nil { + hasErr = true + nAttrs = append(nAttrs, slog.String(s.opts.ErrorKey, ve.Error())) + if span, ok := tracer.SpanFromContext(ctx); ok { + span.SetStatus(tracer.SpanStatusError, ve.Error()) + } + break + } + } + + if !hasErr { + for _, attr := range nAttrs { + if ve, ok := attr.(error); ok && ve != nil { + hasErr = true + nAttrs = append(nAttrs, slog.String(s.opts.ErrorKey, ve.Error())) + if span, ok := tracer.SpanFromContext(ctx); ok { + span.SetStatus(tracer.SpanStatusError, ve.Error()) + } + break + } + } + } + + if s.opts.AddStacktrace && lvl == logger.ErrorLevel { + stackInfo := make([]byte, 1024*1024) + if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { + traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) + if len(traceLines) != 0 { + nAttrs = append(nAttrs, slog.String(s.opts.StacktraceKey, traceLines[len(traceLines)-1])) + } + } + } + + var pcs [1]uintptr + runtime.Callers(defaultCallerSkipCount, pcs[:]) // skip [Callers, printLog, LogLvlMethod] + r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), msg, pcs[0]) + r.Add(nAttrs...) + _ = s.handler.Handle(ctx, r) +} + func NewLogger(opts ...logger.Option) logger.Logger { s := &slogLogger{ opts: logger.NewOptions(opts...), -- 2.45.2 From 4a787dd2c35f7b0e36527477cb6ae34481637664 Mon Sep 17 00:00:00 2001 From: Evstigneev Denis Date: Fri, 11 Oct 2024 15:54:46 +0300 Subject: [PATCH 08/10] refactor micro && logger interface && upate printlogs --- broker/memory/memory.go | 5 +- config/config.go | 13 +- flow/default.go | 28 +-- fsm/fsm_test.go | 2 +- logger/logger.go | 140 +------------- logger/noop.go | 14 +- logger/slog/slog.go | 319 +++----------------------------- logger/slog/slog_test.go | 2 +- network/tunnel/broker/broker.go | 16 +- register/memory/memory.go | 15 +- server/noop.go | 2 +- service.go | 4 +- tracer/memory/memory_test.go | 4 +- util/id/id.go | 2 +- 14 files changed, 86 insertions(+), 480 deletions(-) diff --git a/broker/memory/memory.go b/broker/memory/memory.go index 9fa1551c..a2cce27c 100644 --- a/broker/memory/memory.go +++ b/broker/memory/memory.go @@ -2,6 +2,7 @@ package broker import ( "context" + "fmt" "sync" "go.unistack.org/micro/v3/broker" @@ -206,7 +207,7 @@ func (m *memoryBroker) publish(ctx context.Context, msgs []*broker.Message, opts } } else if sub.opts.AutoAck { if err = ms.Ack(); err != nil { - m.opts.Logger.Errorf(m.opts.Context, "ack failed: %v", err) + m.opts.Logger.Error(m.opts.Context, fmt.Sprintf("ack failed: %v", err), err) } } // single processing @@ -221,7 +222,7 @@ func (m *memoryBroker) publish(ctx context.Context, msgs []*broker.Message, opts } } else if sub.opts.AutoAck { if err = p.Ack(); err != nil { - m.opts.Logger.Errorf(m.opts.Context, "ack failed: %v", err) + m.opts.Logger.Error(m.opts.Context, fmt.Sprintf("ack failed: %v", err), err) } } } diff --git a/config/config.go b/config/config.go index aa8ff16f..ac1a30c8 100644 --- a/config/config.go +++ b/config/config.go @@ -4,6 +4,7 @@ package config import ( "context" "errors" + "fmt" "reflect" "time" ) @@ -138,7 +139,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Errorf(ctx, "%s BeforeLoad err: %v", c.String(), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeLoad err: %v", c.String(), err), err) if !c.Options().AllowFail { return err } @@ -153,7 +154,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Errorf(ctx, "%s AfterLoad err: %v", c.String(), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterLoad err: %v", c.String(), err), err) if !c.Options().AllowFail { return err } @@ -168,7 +169,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Errorf(ctx, "%s BeforeSave err: %v", c.String(), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeSave err: %v", c.String(), err), err) if !c.Options().AllowFail { return err } @@ -183,7 +184,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Errorf(ctx, "%s AfterSave err: %v", c.String(), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterSave err: %v", c.String(), err), err) if !c.Options().AllowFail { return err } @@ -198,7 +199,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Errorf(ctx, "%s BeforeInit err: %v", c.String(), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeInit err: %v", c.String(), err), err) if !c.Options().AllowFail { return err } @@ -213,7 +214,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Errorf(ctx, "%s AfterInit err: %v", c.String(), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterInit err: %v", c.String(), err), err) if !c.Options().AllowFail { return err } diff --git a/flow/default.go b/flow/default.go index af0e018a..f8cc7f04 100644 --- a/flow/default.go +++ b/flow/default.go @@ -188,7 +188,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu steps, err := w.getSteps(options.Start, options.Reverse) if err != nil { if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusPending.String())}); werr != nil { - w.opts.Logger.Errorf(w.opts.Context, "store error: %v", werr) + w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) } return "", err } @@ -212,7 +212,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu done := make(chan struct{}) if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusRunning.String())}); werr != nil { - w.opts.Logger.Errorf(w.opts.Context, "store error: %v", werr) + w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) return eid, werr } for idx := range steps { @@ -237,7 +237,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu return } if w.opts.Logger.V(logger.TraceLevel) { - w.opts.Logger.Tracef(nctx, "will be executed %v", steps[idx][nidx]) + w.opts.Logger.Trace(nctx, fmt.Sprintf("will be executed %v", steps[idx][nidx])) } cstep := steps[idx][nidx] // nolint: nestif @@ -257,21 +257,21 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu if serr != nil { step.SetStatus(StatusFailure) if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"rsp", serr); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Errorf(ctx, "store write error: %v", werr) + w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) } if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"status", &codec.Frame{Data: []byte(StatusFailure.String())}); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Errorf(ctx, "store write error: %v", werr) + w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) } cherr <- serr return } if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"rsp", rsp); werr != nil { - w.opts.Logger.Errorf(ctx, "store write error: %v", werr) + w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) cherr <- werr return } if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"status", &codec.Frame{Data: []byte(StatusSuccess.String())}); werr != nil { - w.opts.Logger.Errorf(ctx, "store write error: %v", werr) + w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) cherr <- werr return } @@ -290,16 +290,16 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu if serr != nil { cstep.SetStatus(StatusFailure) if werr := stepStore.Write(ctx, cstep.ID()+w.opts.Store.Options().Separator+"rsp", serr); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Errorf(ctx, "store write error: %v", werr) + w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) } if werr := stepStore.Write(ctx, cstep.ID()+w.opts.Store.Options().Separator+"status", &codec.Frame{Data: []byte(StatusFailure.String())}); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Errorf(ctx, "store write error: %v", werr) + w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) } cherr <- serr return } if werr := stepStore.Write(ctx, cstep.ID()+w.opts.Store.Options().Separator+"rsp", rsp); werr != nil { - w.opts.Logger.Errorf(ctx, "store write error: %v", werr) + w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) cherr <- werr return } @@ -317,7 +317,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu return eid, nil } - logger.Tracef(ctx, "wait for finish or error") + logger.DefaultLogger.Trace(ctx, "wait for finish or error") select { case <-nctx.Done(): err = nctx.Err() @@ -333,15 +333,15 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu switch { case nctx.Err() != nil: if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusAborted.String())}); werr != nil { - w.opts.Logger.Errorf(w.opts.Context, "store error: %v", werr) + w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) } case err == nil: if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusSuccess.String())}); werr != nil { - w.opts.Logger.Errorf(w.opts.Context, "store error: %v", werr) + w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) } case err != nil: if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusFailure.String())}); werr != nil { - w.opts.Logger.Errorf(w.opts.Context, "store error: %v", werr) + w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) } } diff --git a/fsm/fsm_test.go b/fsm/fsm_test.go index ad7d706e..d39920c8 100644 --- a/fsm/fsm_test.go +++ b/fsm/fsm_test.go @@ -17,7 +17,7 @@ func TestFSMStart(t *testing.T) { wrapper := func(next StateFunc) StateFunc { return func(sctx context.Context, s State, opts ...StateOption) (State, error) { - sctx = logger.NewContext(sctx, logger.Fields("state", s.Name())) + sctx = logger.NewContext(sctx, logger.DefaultLogger.Fields("state", s.Name())) return next(sctx, s, opts...) } } diff --git a/logger/logger.go b/logger/logger.go index aac0734c..33622533 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -31,40 +31,19 @@ type Logger interface { // Fields set fields to always be logged with keyval pairs Fields(fields ...interface{}) Logger // Info level message - Info(ctx context.Context, args ...interface{}) + Info(ctx context.Context, msg string, args ...interface{}) // Trace level message - Trace(ctx context.Context, args ...interface{}) + Trace(ctx context.Context, msg string, args ...interface{}) // Debug level message - Debug(ctx context.Context, args ...interface{}) + Debug(ctx context.Context, msg string, args ...interface{}) // Warn level message - Warn(ctx context.Context, args ...interface{}) + Warn(ctx context.Context, msg string, args ...interface{}) // Error level message - Error(ctx context.Context, args ...interface{}) + Error(ctx context.Context, msg string, args ...interface{}) // Fatal level message - Fatal(ctx context.Context, args ...interface{}) - // Infof level message - // DEPRECATED - Infof(ctx context.Context, msg string, args ...interface{}) - // Tracef level message - // DEPRECATED - Tracef(ctx context.Context, msg string, args ...interface{}) - // Debugf level message - // DEPRECATED - Debugf(ctx context.Context, msg string, args ...interface{}) - // Warnf level message - // DEPRECATED - Warnf(ctx context.Context, msg string, args ...interface{}) - // Errorf level message - // DEPRECATED - Errorf(ctx context.Context, msg string, args ...interface{}) - // Fatalf level message - // DEPRECATED - Fatalf(ctx context.Context, msg string, args ...interface{}) + Fatal(ctx context.Context, msg string, args ...interface{}) // Log logs message with needed level - Log(ctx context.Context, level Level, args ...interface{}) - // Logf logs message with needed level - // DEPRECATED - Logf(ctx context.Context, level Level, msg string, args ...interface{}) + Log(ctx context.Context, level Level, msg string, args ...interface{}) // Name returns broker instance name Name() string // String returns the type of logger @@ -73,108 +52,3 @@ type Logger interface { // Field contains keyval pair type Field interface{} - -// Info writes msg to default logger on info level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Info(ctx context.Context, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Info(ctx, args...) -} - -// Error writes msg to default logger on error level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Error(ctx context.Context, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Error(ctx, args...) -} - -// Debug writes msg to default logger on debug level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Debug(ctx context.Context, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Debug(ctx, args...) -} - -// Warn writes msg to default logger on warn level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Warn(ctx context.Context, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Warn(ctx, args...) -} - -// Trace writes msg to default logger on trace level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Trace(ctx context.Context, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Trace(ctx, args...) -} - -// Fatal writes msg to default logger on fatal level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Fatal(ctx context.Context, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Fatal(ctx, args...) -} - -// Infof writes formatted msg to default logger on info level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Infof(ctx context.Context, msg string, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Infof(ctx, msg, args...) -} - -// Errorf writes formatted msg to default logger on error level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Errorf(ctx context.Context, msg string, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Errorf(ctx, msg, args...) -} - -// Debugf writes formatted msg to default logger on debug level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Debugf(ctx context.Context, msg string, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Debugf(ctx, msg, args...) -} - -// Warnf writes formatted msg to default logger on warn level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Warnf(ctx context.Context, msg string, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Warnf(ctx, msg, args...) -} - -// Tracef writes formatted msg to default logger on trace level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Tracef(ctx context.Context, msg string, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Tracef(ctx, msg, args...) -} - -// Fatalf writes formatted msg to default logger on fatal level -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Fatalf(ctx context.Context, msg string, args ...interface{}) { - DefaultLogger.Clone(WithCallerSkipCount(DefaultCallerSkipCount+1)).Fatalf(ctx, msg, args...) -} - -// V returns true if passed level enabled in default logger -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func V(level Level) bool { - return DefaultLogger.V(level) -} - -// Init initialize logger -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Init(opts ...Option) error { - return DefaultLogger.Init(opts...) -} - -// Fields create logger with specific fields -// -// Deprecated: Dont use logger methods directly, use instance of logger to avoid additional allocations -func Fields(fields ...interface{}) Logger { - return DefaultLogger.Fields(fields...) -} diff --git a/logger/noop.go b/logger/noop.go index 17f3608b..5d95e9b2 100644 --- a/logger/noop.go +++ b/logger/noop.go @@ -51,25 +51,25 @@ func (l *noopLogger) String() string { return "noop" } -func (l *noopLogger) Log(ctx context.Context, lvl Level, attrs ...interface{}) { +func (l *noopLogger) Log(ctx context.Context, lvl Level, msg string, attrs ...interface{}) { } -func (l *noopLogger) Info(ctx context.Context, attrs ...interface{}) { +func (l *noopLogger) Info(ctx context.Context, msg string, attrs ...interface{}) { } -func (l *noopLogger) Debug(ctx context.Context, attrs ...interface{}) { +func (l *noopLogger) Debug(ctx context.Context, msg string, attrs ...interface{}) { } -func (l *noopLogger) Error(ctx context.Context, attrs ...interface{}) { +func (l *noopLogger) Error(ctx context.Context, msg string, attrs ...interface{}) { } -func (l *noopLogger) Trace(ctx context.Context, attrs ...interface{}) { +func (l *noopLogger) Trace(ctx context.Context, msg string, attrs ...interface{}) { } -func (l *noopLogger) Warn(ctx context.Context, attrs ...interface{}) { +func (l *noopLogger) Warn(ctx context.Context, msg string, attrs ...interface{}) { } -func (l *noopLogger) Fatal(ctx context.Context, attrs ...interface{}) { +func (l *noopLogger) Fatal(ctx context.Context, msg string, attrs ...interface{}) { } func (l *noopLogger) Logf(ctx context.Context, lvl Level, msg string, attrs ...interface{}) { diff --git a/logger/slog/slog.go b/logger/slog/slog.go index b2260a58..1f617e46 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -2,7 +2,6 @@ package slog import ( "context" - "fmt" "log/slog" "os" "regexp" @@ -157,231 +156,33 @@ func (s *slogLogger) Init(opts ...logger.Option) error { return nil } -func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, attrs ...interface{}) { - s.printLog(ctx, lvl, attrs...) +func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { + s.printLog(ctx, lvl, msg, attrs...) } -// Logf DEPRECATED -func (s *slogLogger) Logf(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() - if !s.V(lvl) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(2, pcs[:]) // skip [Callers, Logf] - r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - if s.opts.AddStacktrace && lvl == logger.ErrorLevel { - stackInfo := make([]byte, 1024*1024) - if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { - traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) - if len(traceLines) != 0 { - attrs = append(attrs, (slog.String(s.opts.StacktraceKey, traceLines[len(traceLines)-1]))) - } - } - } - r.Add(attrs[1:]...) - r.Attrs(func(a slog.Attr) bool { - if a.Key == s.opts.ErrorKey { - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, a.Value.String()) - return false - } - } - return true - }) - _ = s.handler.Handle(ctx, r) +func (s *slogLogger) Info(ctx context.Context, msg string, attrs ...interface{}) { + s.printLog(ctx, logger.InfoLevel, msg, attrs...) } -func (s *slogLogger) Info(ctx context.Context, attrs ...interface{}) { - s.printLog(ctx, logger.InfoLevel, attrs...) +func (s *slogLogger) Debug(ctx context.Context, msg string, attrs ...interface{}) { + s.printLog(ctx, logger.DebugLevel, msg, attrs...) } -// Infof DEPRECATED -func (s *slogLogger) Infof(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.InfoLevel.String()).Inc() - if !s.V(logger.InfoLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(2, pcs[:]) // skip [Callers, Infof] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelInfo, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs...) - _ = s.handler.Handle(ctx, r) +func (s *slogLogger) Trace(ctx context.Context, msg string, attrs ...interface{}) { + s.printLog(ctx, logger.TraceLevel, msg, attrs...) } -func (s *slogLogger) Debug(ctx context.Context, attrs ...interface{}) { - s.printLog(ctx, logger.DebugLevel, attrs...) +func (s *slogLogger) Error(ctx context.Context, msg string, attrs ...interface{}) { + s.printLog(ctx, logger.ErrorLevel, msg, attrs...) } -// Debugf DEPRECATED -func (s *slogLogger) Debugf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.DebugLevel.String()).Inc() - if !s.V(logger.DebugLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(2, pcs[:]) // skip [Callers, Debugf] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs...) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Trace(ctx context.Context, attrs ...interface{}) { - s.printLog(ctx, logger.TraceLevel, attrs...) -} - -// Tracef DEPRECATED -func (s *slogLogger) Tracef(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.TraceLevel.String()).Inc() - if !s.V(logger.TraceLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(2, pcs[:]) // skip [Callers, Tracef] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelDebug-1, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Error(ctx context.Context, attrs ...interface{}) { - s.printLog(ctx, logger.ErrorLevel, attrs...) -} - -// Errorf DEPRECATED -func (s *slogLogger) Errorf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.ErrorLevel.String()).Inc() - if !s.V(logger.ErrorLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(2, pcs[:]) // skip [Callers, Errorf] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - if s.opts.AddStacktrace { - stackInfo := make([]byte, 1024*1024) - if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { - traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) - if len(traceLines) != 0 { - attrs = append(attrs, slog.String("stacktrace", traceLines[len(traceLines)-1])) - } - } - } - r.Add(attrs...) - r.Attrs(func(a slog.Attr) bool { - if a.Key == s.opts.ErrorKey { - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, a.Value.String()) - return false - } - } - return true - }) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) Fatal(ctx context.Context, attrs ...interface{}) { - s.printLog(ctx, logger.FatalLevel, attrs...) +func (s *slogLogger) Fatal(ctx context.Context, msg string, attrs ...interface{}) { + s.printLog(ctx, logger.FatalLevel, msg, attrs...) os.Exit(1) } -// Fatalf DEPRECATED -func (s *slogLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.FatalLevel.String()).Inc() - if !s.V(logger.FatalLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(2, pcs[:]) // skip [Callers, Fatalf] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelError+1, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs...) - _ = s.handler.Handle(ctx, r) - os.Exit(1) -} - -func (s *slogLogger) Warn(ctx context.Context, attrs ...interface{}) { - s.printLog(ctx, logger.WarnLevel, attrs...) -} - -// Warnf DEPRECATED -func (s *slogLogger) Warnf(ctx context.Context, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.WarnLevel.String()).Inc() - if !s.V(logger.WarnLevel) || len(attrs) == 0 { - return - } - var pcs [1]uintptr - runtime.Callers(2, pcs[:]) // skip [Callers, Warnf] - r := slog.NewRecord(s.opts.TimeFunc(), slog.LevelWarn, msg, pcs[0]) - for _, fn := range s.opts.ContextAttrFuncs { - attrs = append(attrs, fn(ctx)...) - } - - for idx, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - break - } - } - r.Add(attrs[1:]...) - _ = s.handler.Handle(ctx, r) +func (s *slogLogger) Warn(ctx context.Context, msg string, attrs ...interface{}) { + s.printLog(ctx, logger.WarnLevel, msg, attrs...) } func (s *slogLogger) Name() string { @@ -392,41 +193,26 @@ func (s *slogLogger) String() string { return "slog" } -func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, attrs ...interface{}) { +func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() - if !s.V(lvl) || len(attrs) == 0 { + if !s.V(lvl) { return } - msg := attrs[0] - attrs = prepareAttributes(attrs[1:]) - - ve, hasErr := msg.(error) - if hasErr && ve != nil { - attrs = append(attrs, slog.String(s.opts.ErrorKey, ve.Error())) - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, ve.Error()) - } - } + attrs = prepareAttributes(attrs) for _, fn := range s.opts.ContextAttrFuncs { a := prepareAttributes(fn(ctx)) attrs = append(attrs, a...) } - if !hasErr { - for idx, attr := range attrs { - if ve, hasErr = attr.(error); hasErr && ve != nil { - if idx%2 == 1 { - attrs = append(attrs, slog.String(s.opts.ErrorKey, ve.Error())) - } else { - attrs[idx] = slog.String(s.opts.ErrorKey, ve.Error()) - } - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, ve.Error()) - } - break + for _, attr := range attrs { + if ve, hasErr := attr.(error); hasErr && ve != nil { + attrs = append(attrs, slog.String(s.opts.ErrorKey, ve.Error())) + if span, ok := tracer.SpanFromContext(ctx); ok { + span.SetStatus(tracer.SpanStatusError, ve.Error()) } + break } } @@ -440,66 +226,10 @@ func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, attrs ...in } } - var pcs [1]uintptr - runtime.Callers(defaultCallerSkipCount, pcs[:]) // skip [Callers, printLog, LogLvlMethod] - r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), fmt.Sprintf("%s", msg), pcs[0]) - r.Add(attrs...) - _ = s.handler.Handle(ctx, r) -} - -func (s *slogLogger) printLogf(ctx context.Context, lvl logger.Level, format string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() - if !s.V(lvl) { - return - } - - msg := fmt.Sprintf(format, attrs...) - - var nAttrs []interface{} - for _, fn := range s.opts.ContextAttrFuncs { - a := prepareAttributes(fn(ctx)) - nAttrs = append(nAttrs, a...) - } - - hasErr := false - for _, attr := range attrs { - if ve, ok := attr.(error); ok && ve != nil { - hasErr = true - nAttrs = append(nAttrs, slog.String(s.opts.ErrorKey, ve.Error())) - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, ve.Error()) - } - break - } - } - - if !hasErr { - for _, attr := range nAttrs { - if ve, ok := attr.(error); ok && ve != nil { - hasErr = true - nAttrs = append(nAttrs, slog.String(s.opts.ErrorKey, ve.Error())) - if span, ok := tracer.SpanFromContext(ctx); ok { - span.SetStatus(tracer.SpanStatusError, ve.Error()) - } - break - } - } - } - - if s.opts.AddStacktrace && lvl == logger.ErrorLevel { - stackInfo := make([]byte, 1024*1024) - if stackSize := runtime.Stack(stackInfo, false); stackSize > 0 { - traceLines := reTrace.Split(string(stackInfo[:stackSize]), -1) - if len(traceLines) != 0 { - nAttrs = append(nAttrs, slog.String(s.opts.StacktraceKey, traceLines[len(traceLines)-1])) - } - } - } - var pcs [1]uintptr runtime.Callers(defaultCallerSkipCount, pcs[:]) // skip [Callers, printLog, LogLvlMethod] r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), msg, pcs[0]) - r.Add(nAttrs...) + r.Add(attrs...) _ = s.handler.Handle(ctx, r) } @@ -546,7 +276,6 @@ func slogToLoggerLevel(level slog.Level) logger.Level { } func prepareAttributes(attrs []interface{}) []interface{} { - if len(attrs)%2 == 1 { attrs = append(attrs, badKey) attrs[len(attrs)-1], attrs[len(attrs)-2] = attrs[len(attrs)-2], attrs[len(attrs)-1] diff --git a/logger/slog/slog_test.go b/logger/slog/slog_test.go index 8f94d663..f8daace0 100644 --- a/logger/slog/slog_test.go +++ b/logger/slog/slog_test.go @@ -47,7 +47,7 @@ func TestErrorf(t *testing.T) { t.Fatalf("logger BADKEY not works, buf contains: %s", buf.Bytes()) } - l.Log(ctx, logger.ErrorLevel, errors.New("error msg")) + l.Log(ctx, logger.ErrorLevel, "", errors.New("error msg")) if !bytes.Contains(buf.Bytes(), []byte(`"error":"error msg"`)) { t.Fatalf("logger error not works, buf contains: %s", buf.Bytes()) } diff --git a/network/tunnel/broker/broker.go b/network/tunnel/broker/broker.go index 95a2f20f..921d1853 100644 --- a/network/tunnel/broker/broker.go +++ b/network/tunnel/broker/broker.go @@ -177,12 +177,12 @@ func (t *tunBatchSubscriber) run() { // receive message m := new(transport.Message) if err := c.Recv(m); err != nil { - if logger.V(logger.ErrorLevel) { - logger.Error(t.opts.Context, err.Error()) + if logger.DefaultLogger.V(logger.ErrorLevel) { + logger.DefaultLogger.Error(t.opts.Context, err.Error(), err) } if err = c.Close(); err != nil { - if logger.V(logger.ErrorLevel) { - logger.Error(t.opts.Context, err.Error()) + if logger.DefaultLogger.V(logger.ErrorLevel) { + logger.DefaultLogger.Error(t.opts.Context, err.Error(), err) } } continue @@ -222,12 +222,12 @@ func (t *tunSubscriber) run() { // receive message m := new(transport.Message) if err := c.Recv(m); err != nil { - if logger.V(logger.ErrorLevel) { - logger.Error(t.opts.Context, err.Error()) + if logger.DefaultLogger.V(logger.ErrorLevel) { + logger.DefaultLogger.Error(t.opts.Context, err.Error(), err) } if err = c.Close(); err != nil { - if logger.V(logger.ErrorLevel) { - logger.Error(t.opts.Context, err.Error()) + if logger.DefaultLogger.V(logger.ErrorLevel) { + logger.DefaultLogger.Error(t.opts.Context, err.Error(), err) } } continue diff --git a/register/memory/memory.go b/register/memory/memory.go index b674bddd..ed241c4f 100644 --- a/register/memory/memory.go +++ b/register/memory/memory.go @@ -2,6 +2,7 @@ package register import ( "context" + "fmt" "sync" "time" @@ -64,7 +65,7 @@ func (m *memory) ttlPrune() { for id, n := range record.Nodes { if n.TTL != 0 && time.Since(n.LastSeen) > n.TTL { if m.opts.Logger.V(logger.DebugLevel) { - m.opts.Logger.Debugf(m.opts.Context, "Register TTL expired for node %s of service %s", n.ID, service) + m.opts.Logger.Debug(m.opts.Context, fmt.Sprintf("Register TTL expired for node %s of service %s", n.ID, service)) } delete(m.records[domain][service][version].Nodes, id) } @@ -151,7 +152,7 @@ func (m *memory) Register(ctx context.Context, s *register.Service, opts ...regi if _, ok := srvs[s.Name][s.Version]; !ok { srvs[s.Name][s.Version] = r if m.opts.Logger.V(logger.DebugLevel) { - m.opts.Logger.Debugf(m.opts.Context, "Register added new service: %s, version: %s", s.Name, s.Version) + m.opts.Logger.Debug(m.opts.Context, fmt.Sprintf("Register added new service: %s, version: %s", s.Name, s.Version)) } m.records[options.Domain] = srvs go m.sendEvent(®ister.Result{Action: "create", Service: s}) @@ -191,14 +192,14 @@ func (m *memory) Register(ctx context.Context, s *register.Service, opts ...regi if addedNodes { if m.opts.Logger.V(logger.DebugLevel) { - m.opts.Logger.Debugf(m.opts.Context, "Register added new node to service: %s, version: %s", s.Name, s.Version) + m.opts.Logger.Debug(m.opts.Context, fmt.Sprintf("Register added new node to service: %s, version: %s", s.Name, s.Version)) } go m.sendEvent(®ister.Result{Action: "update", Service: s}) } else { // refresh TTL and timestamp for _, n := range s.Nodes { if m.opts.Logger.V(logger.DebugLevel) { - m.opts.Logger.Debugf(m.opts.Context, "Updated registration for service: %s, version: %s", s.Name, s.Version) + m.opts.Logger.Debug(m.opts.Context, fmt.Sprintf("Updated registration for service: %s, version: %s", s.Name, s.Version)) } srvs[s.Name][s.Version].Nodes[n.ID].TTL = options.TTL srvs[s.Name][s.Version].Nodes[n.ID].LastSeen = time.Now() @@ -243,7 +244,7 @@ func (m *memory) Deregister(ctx context.Context, s *register.Service, opts ...re for _, n := range s.Nodes { if _, ok := version.Nodes[n.ID]; ok { if m.opts.Logger.V(logger.DebugLevel) { - m.opts.Logger.Debugf(m.opts.Context, "Register removed node from service: %s, version: %s", s.Name, s.Version) + m.opts.Logger.Debug(m.opts.Context, fmt.Sprintf("Register removed node from service: %s, version: %s", s.Name, s.Version)) } delete(version.Nodes, n.ID) } @@ -264,7 +265,7 @@ func (m *memory) Deregister(ctx context.Context, s *register.Service, opts ...re go m.sendEvent(®ister.Result{Action: "delete", Service: s}) if m.opts.Logger.V(logger.DebugLevel) { - m.opts.Logger.Debugf(m.opts.Context, "Register removed service: %s", s.Name) + m.opts.Logger.Debug(m.opts.Context, fmt.Sprintf("Register removed service: %s", s.Name)) } return nil } @@ -273,7 +274,7 @@ func (m *memory) Deregister(ctx context.Context, s *register.Service, opts ...re delete(m.records[options.Domain][s.Name], s.Version) go m.sendEvent(®ister.Result{Action: "delete", Service: s}) if m.opts.Logger.V(logger.DebugLevel) { - m.opts.Logger.Debugf(m.opts.Context, "Register removed service: %s, version: %s", s.Name, s.Version) + m.opts.Logger.Debug(m.opts.Context, fmt.Sprintf("Register removed service: %s, version: %s", s.Name, s.Version)) } return nil diff --git a/server/noop.go b/server/noop.go index 6d2ecc05..c4acf493 100644 --- a/server/noop.go +++ b/server/noop.go @@ -459,7 +459,7 @@ func (n *noopServer) Start() error { } } else if rerr != nil && !registered { if config.Logger.V(logger.ErrorLevel) { - config.Logger.Errorf(n.opts.Context, fmt.Sprintf("server %s-%s register check error", config.Name, config.ID), rerr) + config.Logger.Error(n.opts.Context, fmt.Sprintf("server %s-%s register check error", config.Name, config.ID), rerr) } continue } diff --git a/service.go b/service.go index 7a9c3a46..a15897d4 100644 --- a/service.go +++ b/service.go @@ -276,7 +276,7 @@ func (s *service) Start() error { } if config.Loggers[0].V(logger.InfoLevel) { - config.Loggers[0].Infof(s.opts.Context, "starting [service] %s version %s", s.Options().Name, s.Options().Version) + config.Loggers[0].Info(s.opts.Context, fmt.Sprintf("starting [service] %s version %s", s.Options().Name, s.Options().Version)) } if len(s.opts.Servers) == 0 { @@ -322,7 +322,7 @@ func (s *service) Stop() error { s.RUnlock() if config.Loggers[0].V(logger.InfoLevel) { - config.Loggers[0].Infof(s.opts.Context, "stoppping [service] %s", s.Name()) + config.Loggers[0].Info(s.opts.Context, fmt.Sprintf("stoppping [service] %s", s.Name())) } var err error diff --git a/tracer/memory/memory_test.go b/tracer/memory/memory_test.go index 7a6dddd6..bf2b88de 100644 --- a/tracer/memory/memory_test.go +++ b/tracer/memory/memory_test.go @@ -17,14 +17,14 @@ func TestLoggerWithTracer(t *testing.T) { buf := bytes.NewBuffer(nil) logger.DefaultLogger = slog.NewLogger(logger.WithOutput(buf)) - if err := logger.Init(); err != nil { + if err := logger.DefaultLogger.Init(); err != nil { t.Fatal(err) } var span tracer.Span tr := NewTracer() ctx, span = tr.Start(ctx, "test1") - logger.Error(ctx, "my test error", fmt.Errorf("error")) + logger.DefaultLogger.Error(ctx, "my test error", fmt.Errorf("error")) if !strings.Contains(buf.String(), span.TraceID()) { t.Fatalf("log does not contains trace id: %s", buf.Bytes()) diff --git a/util/id/id.go b/util/id/id.go index 2d094f1f..f7d34563 100644 --- a/util/id/id.go +++ b/util/id/id.go @@ -71,7 +71,7 @@ func New(opts ...Option) (string, error) { func Must(opts ...Option) string { id, err := New(opts...) if err != nil { - logger.Fatal(context.TODO(), err) + logger.DefaultLogger.Fatal(context.TODO(), "Must call is failed", err) } return id } -- 2.45.2 From ced277ff5724cecc4ea9bea4cb80c2d00d6004b5 Mon Sep 17 00:00:00 2001 From: Evstigneev Denis Date: Fri, 11 Oct 2024 16:48:14 +0300 Subject: [PATCH 09/10] undo remove SkipCallerCount --- logger/logger.go | 2 ++ logger/options.go | 12 ++++++++++++ logger/slog/slog.go | 4 +--- 3 files changed, 15 insertions(+), 3 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 33622533..310d56f2 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -14,6 +14,8 @@ var ( DefaultLogger Logger = NewLogger() // DefaultLevel used by logger DefaultLevel = InfoLevel + // defaultCallerSkipCount used by logger + defaultCallerSkipCount = 3 ) // Logger is a generic logging interface diff --git a/logger/options.go b/logger/options.go index bcf31142..6a5b717d 100644 --- a/logger/options.go +++ b/logger/options.go @@ -23,6 +23,8 @@ type Options struct { Name string // Fields holds additional metadata Fields []interface{} + // callerSkipCount number of frmaes to skip + CallerSkipCount int // ContextAttrFuncs contains funcs that executed before log func on context ContextAttrFuncs []ContextAttrFunc // TimeKey is the key used for the time of the log call @@ -52,6 +54,7 @@ type Options struct { // NewOptions creates new options struct func NewOptions(opts ...Option) Options { options := Options{ + CallerSkipCount: defaultCallerSkipCount, Level: DefaultLevel, Fields: make([]interface{}, 0, 6), Out: os.Stderr, @@ -184,3 +187,12 @@ func WithMicroKeys() Option { o.ErrorKey = "error" } } + +// WithAddCallerSkipCount add skip count for copy logger +func WithAddCallerSkipCount(n int) Option { + return func(o *Options) { + if n > 0 { + o.CallerSkipCount += n + } + } +} diff --git a/logger/slog/slog.go b/logger/slog/slog.go index 1f617e46..c195bf36 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -16,8 +16,6 @@ import ( const ( badKey = "!BADKEY" - // DefaultCallerSkipCount used by logger - defaultCallerSkipCount = 3 ) const emptyMSg = "!EMPTYMSG" @@ -227,7 +225,7 @@ func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, msg string, } var pcs [1]uintptr - runtime.Callers(defaultCallerSkipCount, pcs[:]) // skip [Callers, printLog, LogLvlMethod] + runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, printLog, LogLvlMethod] r := slog.NewRecord(s.opts.TimeFunc(), loggerToSlogLevel(lvl), msg, pcs[0]) r.Add(attrs...) _ = s.handler.Handle(ctx, r) -- 2.45.2 From 8a9243636eaf4da5cf46af7698ec5b74248919f1 Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Sat, 12 Oct 2024 12:36:08 +0300 Subject: [PATCH 10/10] small fixups Signed-off-by: Vasiliy Tolstov --- broker/memory/memory.go | 7 +++---- config/config.go | 12 ++++++------ flow/default.go | 24 ++++++++++++------------ logger/logger.go | 2 -- logger/noop.go | 26 +++++--------------------- logger/options.go | 1 - logger/slog/slog.go | 7 +++++-- 7 files changed, 31 insertions(+), 48 deletions(-) diff --git a/broker/memory/memory.go b/broker/memory/memory.go index a2cce27c..de8f1c73 100644 --- a/broker/memory/memory.go +++ b/broker/memory/memory.go @@ -2,7 +2,6 @@ package broker import ( "context" - "fmt" "sync" "go.unistack.org/micro/v3/broker" @@ -207,7 +206,7 @@ func (m *memoryBroker) publish(ctx context.Context, msgs []*broker.Message, opts } } else if sub.opts.AutoAck { if err = ms.Ack(); err != nil { - m.opts.Logger.Error(m.opts.Context, fmt.Sprintf("ack failed: %v", err), err) + m.opts.Logger.Error(m.opts.Context, "broker ack error", err) } } // single processing @@ -218,11 +217,11 @@ func (m *memoryBroker) publish(ctx context.Context, msgs []*broker.Message, opts if eh != nil { _ = eh(p) } else if m.opts.Logger.V(logger.ErrorLevel) { - m.opts.Logger.Error(m.opts.Context, err.Error()) + m.opts.Logger.Error(m.opts.Context, "broker handler error", err) } } else if sub.opts.AutoAck { if err = p.Ack(); err != nil { - m.opts.Logger.Error(m.opts.Context, fmt.Sprintf("ack failed: %v", err), err) + m.opts.Logger.Error(m.opts.Context, "broker ack error", err) } } } diff --git a/config/config.go b/config/config.go index ac1a30c8..0ca629e4 100644 --- a/config/config.go +++ b/config/config.go @@ -139,7 +139,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeLoad err: %v", c.String(), err), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeLoad error", c.String()), err) if !c.Options().AllowFail { return err } @@ -154,7 +154,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterLoad err: %v", c.String(), err), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterLoad error", c.String()), err) if !c.Options().AllowFail { return err } @@ -169,7 +169,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeSave err: %v", c.String(), err), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeSave error", c.String()), err) if !c.Options().AllowFail { return err } @@ -184,7 +184,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterSave err: %v", c.String(), err), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterSave error", c.String()), err) if !c.Options().AllowFail { return err } @@ -199,7 +199,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeInit err: %v", c.String(), err), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s BeforeInit error", c.String()), err) if !c.Options().AllowFail { return err } @@ -214,7 +214,7 @@ var ( return nil } if err := fn(ctx, c); err != nil { - c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterInit err: %v", c.String(), err), err) + c.Options().Logger.Error(ctx, fmt.Sprintf("%s AfterInit error", c.String(), err), err) if !c.Options().AllowFail { return err } diff --git a/flow/default.go b/flow/default.go index f8cc7f04..e07303f2 100644 --- a/flow/default.go +++ b/flow/default.go @@ -188,7 +188,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu steps, err := w.getSteps(options.Start, options.Reverse) if err != nil { if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusPending.String())}); werr != nil { - w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) + w.opts.Logger.Error(w.opts.Context, "store write error", werr) } return "", err } @@ -212,7 +212,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu done := make(chan struct{}) if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusRunning.String())}); werr != nil { - w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) + w.opts.Logger.Error(w.opts.Context, "store write error", werr) return eid, werr } for idx := range steps { @@ -257,21 +257,21 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu if serr != nil { step.SetStatus(StatusFailure) if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"rsp", serr); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) + w.opts.Logger.Error(ctx, "store write error", werr) } if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"status", &codec.Frame{Data: []byte(StatusFailure.String())}); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) + w.opts.Logger.Error(ctx, "store write error", werr) } cherr <- serr return } if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"rsp", rsp); werr != nil { - w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) + w.opts.Logger.Error(ctx, "store write error", werr) cherr <- werr return } if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"status", &codec.Frame{Data: []byte(StatusSuccess.String())}); werr != nil { - w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) + w.opts.Logger.Error(ctx, "store write error", werr) cherr <- werr return } @@ -290,16 +290,16 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu if serr != nil { cstep.SetStatus(StatusFailure) if werr := stepStore.Write(ctx, cstep.ID()+w.opts.Store.Options().Separator+"rsp", serr); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) + w.opts.Logger.Error(ctx, "store write error", werr) } if werr := stepStore.Write(ctx, cstep.ID()+w.opts.Store.Options().Separator+"status", &codec.Frame{Data: []byte(StatusFailure.String())}); werr != nil && w.opts.Logger.V(logger.ErrorLevel) { - w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) + w.opts.Logger.Error(ctx, "store write error", werr) } cherr <- serr return } if werr := stepStore.Write(ctx, cstep.ID()+w.opts.Store.Options().Separator+"rsp", rsp); werr != nil { - w.opts.Logger.Error(ctx, fmt.Sprintf("store write error: %v", werr), werr) + w.opts.Logger.Error(ctx, "store write error", werr) cherr <- werr return } @@ -333,15 +333,15 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu switch { case nctx.Err() != nil: if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusAborted.String())}); werr != nil { - w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) + w.opts.Logger.Error(w.opts.Context, "store write error", werr) } case err == nil: if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusSuccess.String())}); werr != nil { - w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) + w.opts.Logger.Error(w.opts.Context, "store write error", werr) } case err != nil: if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusFailure.String())}); werr != nil { - w.opts.Logger.Error(w.opts.Context, fmt.Sprintf("store error: %v", werr), werr) + w.opts.Logger.Error(w.opts.Context, "store write error", werr) } } diff --git a/logger/logger.go b/logger/logger.go index 310d56f2..33622533 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -14,8 +14,6 @@ var ( DefaultLogger Logger = NewLogger() // DefaultLevel used by logger DefaultLevel = InfoLevel - // defaultCallerSkipCount used by logger - defaultCallerSkipCount = 3 ) // Logger is a generic logging interface diff --git a/logger/noop.go b/logger/noop.go index 5d95e9b2..af9dfeae 100644 --- a/logger/noop.go +++ b/logger/noop.go @@ -4,12 +4,17 @@ import ( "context" ) +const ( + defaultCallerSkipCount = 2 +) + type noopLogger struct { opts Options } func NewLogger(opts ...Option) Logger { options := NewOptions(opts...) + options.CallerSkipCount = defaultCallerSkipCount return &noopLogger{opts: options} } @@ -71,24 +76,3 @@ func (l *noopLogger) Warn(ctx context.Context, msg string, attrs ...interface{}) func (l *noopLogger) Fatal(ctx context.Context, msg string, attrs ...interface{}) { } - -func (l *noopLogger) Logf(ctx context.Context, lvl Level, msg string, attrs ...interface{}) { -} - -func (l *noopLogger) Infof(ctx context.Context, msg string, attrs ...interface{}) { -} - -func (l *noopLogger) Debugf(ctx context.Context, msg string, attrs ...interface{}) { -} - -func (l *noopLogger) Errorf(ctx context.Context, msg string, attrs ...interface{}) { -} - -func (l *noopLogger) Tracef(ctx context.Context, msg string, attrs ...interface{}) { -} - -func (l *noopLogger) Warnf(ctx context.Context, msg string, attrs ...interface{}) { -} - -func (l *noopLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{}) { -} diff --git a/logger/options.go b/logger/options.go index 6a5b717d..ede9a23b 100644 --- a/logger/options.go +++ b/logger/options.go @@ -54,7 +54,6 @@ type Options struct { // NewOptions creates new options struct func NewOptions(opts ...Option) Options { options := Options{ - CallerSkipCount: defaultCallerSkipCount, Level: DefaultLevel, Fields: make([]interface{}, 0, 6), Out: os.Stderr, diff --git a/logger/slog/slog.go b/logger/slog/slog.go index c195bf36..76279083 100644 --- a/logger/slog/slog.go +++ b/logger/slog/slog.go @@ -16,8 +16,9 @@ import ( const ( badKey = "!BADKEY" + // defaultCallerSkipCount used by logger + defaultCallerSkipCount = 3 ) -const emptyMSg = "!EMPTYMSG" var reTrace = regexp.MustCompile(`.*/slog/logger\.go.*\n`) @@ -192,11 +193,12 @@ func (s *slogLogger) String() string { } func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { - s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() if !s.V(lvl) { return } + s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() + attrs = prepareAttributes(attrs) for _, fn := range s.opts.ContextAttrFuncs { @@ -235,6 +237,7 @@ func NewLogger(opts ...logger.Option) logger.Logger { s := &slogLogger{ opts: logger.NewOptions(opts...), } + s.opts.CallerSkipCount = defaultCallerSkipCount return s } -- 2.45.2