update logic prepare msg for output logs

fix changes add prepare Attributes in slog/logger
2024-10-02 18:03:56 +03:00 · 2024-10-02 18:03:56 +03:00 · 1acaa898a2
commit 1acaa898a2
parent fd2b2762e9
6 changed files with 101 additions and 167 deletions
--- 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
--- 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=
--- 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
--- 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
--- 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
+}
--- 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) {