From 1acaa898a221764e7d9c4e280b22c45a4d1fed64 Mon Sep 17 00:00:00 2001 From: devstigneev Date: Wed, 2 Oct 2024 18:03:56 +0300 Subject: [PATCH] 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) {