logger: add ability to fill fileds from context

Signed-off-by: Vasiliy Tolstov <v.tolstov@unistack.org>
2023-10-16 23:43:39 +03:00 · 2023-10-16 23:43:39 +03:00 · 7568779db4
commit 7568779db4
parent 5c3fa31ad2
6 changed files with 133 additions and 64 deletions
--- a/logger/logger.go
+++ b/logger/logger.go
@ -17,6 +17,10 @@ var (
 	DefaultCallerSkipCount = 2
 )

+type ContextAttrFunc func(ctx context.Context) []interface{}
+
+var DefaultContextAttrFuncs []ContextAttrFunc
+
 // Logger is a generic logging interface
 type Logger interface {
 	// Init initialises options
@ -29,57 +33,54 @@ type Logger interface {
 	Level(level Level)
 	// The Logger options
 	Options() Options
-	// Fields set fields to always be logged with keyval pairs
-	Fields(fields ...interface{}) Logger
+	// Attrs set attrs to always be logged with keyval pairs
+	Attrs(attrs ...interface{}) Logger
 	// Info level message
-	Info(ctx context.Context, msg string, args ...interface{})
+	Info(ctx context.Context, msg string, attrs ...interface{})
 	// Tracef level message
-	Trace(ctx context.Context, msg string, args ...interface{})
+	Trace(ctx context.Context, msg string, attrs ...interface{})
 	// Debug level message
-	Debug(ctx context.Context, msg string, args ...interface{})
+	Debug(ctx context.Context, msg string, attrs ...interface{})
 	// Warn level message
-	Warn(ctx context.Context, msg string, args ...interface{})
+	Warn(ctx context.Context, msg string, attrs ...interface{})
 	// Error level message
-	Error(ctx context.Context, msg string, args ...interface{})
+	Error(ctx context.Context, msg string, attrs ...interface{})
 	// Fatal level message
-	Fatal(ctx context.Context, msg string, args ...interface{})
+	Fatal(ctx context.Context, msg string, attrs ...interface{})
 	// Log logs message with needed level
-	Log(ctx context.Context, level Level, msg string, args ...interface{})
+	Log(ctx context.Context, level Level, msg string, attrs ...interface{})
 	// String returns the name of logger
 	String() string
 }

-// Field contains keyval pair
-type Field interface{}
-
 // Info writes formatted msg to default logger on info level
-func Info(ctx context.Context, msg string, args ...interface{}) {
-	DefaultLogger.Info(ctx, msg, args...)
+func Info(ctx context.Context, msg string, attrs ...interface{}) {
+	DefaultLogger.Info(ctx, msg, attrs...)
 }

 // Error writes formatted msg to default logger on error level
-func Error(ctx context.Context, msg string, args ...interface{}) {
-	DefaultLogger.Error(ctx, msg, args...)
+func Error(ctx context.Context, msg string, attrs ...interface{}) {
+	DefaultLogger.Error(ctx, msg, attrs...)
 }

 // Debugf writes formatted msg to default logger on debug level
-func Debugf(ctx context.Context, msg string, args ...interface{}) {
-	DefaultLogger.Debug(ctx, msg, args...)
+func Debugf(ctx context.Context, msg string, attrs ...interface{}) {
+	DefaultLogger.Debug(ctx, msg, attrs...)
 }

 // Warn writes formatted msg to default logger on warn level
-func Warn(ctx context.Context, msg string, args ...interface{}) {
-	DefaultLogger.Warn(ctx, msg, args...)
+func Warn(ctx context.Context, msg string, attrs ...interface{}) {
+	DefaultLogger.Warn(ctx, msg, attrs...)
 }

 // Trace writes formatted msg to default logger on trace level
-func Trace(ctx context.Context, msg string, args ...interface{}) {
-	DefaultLogger.Trace(ctx, msg, args...)
+func Trace(ctx context.Context, msg string, attrs ...interface{}) {
+	DefaultLogger.Trace(ctx, msg, attrs...)
 }

 // Fatal writes formatted msg to default logger on fatal level
-func Fatal(ctx context.Context, msg string, args ...interface{}) {
-	DefaultLogger.Fatal(ctx, msg, args...)
+func Fatal(ctx context.Context, msg string, attrs ...interface{}) {
+	DefaultLogger.Fatal(ctx, msg, attrs...)
 }

 // V returns true if passed level enabled in default logger
@ -87,12 +88,12 @@ func V(level Level) bool {
 	return DefaultLogger.V(level)
 }

-// Init initialize logger
+// Init initialize default logger
 func Init(opts ...options.Option) error {
 	return DefaultLogger.Init(opts...)
 }

-// Fields create logger with specific fields
-func Fields(fields ...interface{}) Logger {
-	return DefaultLogger.Fields(fields...)
+// Attrs create default logger with specific attrs
+func Attrs(attrs ...interface{}) Logger {
+	return DefaultLogger.Attrs(attrs...)
 }
--- a/logger/logger_test.go
+++ b/logger/logger_test.go
@ -15,7 +15,7 @@ func TestContext(t *testing.T) {
 		t.Fatal(err)
 	}

-	nl, ok := FromContext(NewContext(ctx, l.Fields("key", "val")))
+	nl, ok := FromContext(NewContext(ctx, l.Attrs("key", "val")))
 	if !ok {
 		t.Fatal("context without logger")
 	}
@ -25,7 +25,7 @@ func TestContext(t *testing.T) {
 	}
 }

-func TestFields(t *testing.T) {
+func TestAttrs(t *testing.T) {
 	ctx := context.TODO()
 	buf := bytes.NewBuffer(nil)
 	l := NewLogger(WithLevel(TraceLevel), WithOutput(buf))
@ -33,7 +33,7 @@ func TestFields(t *testing.T) {
 		t.Fatal(err)
 	}

-	nl := l.Fields("key", "val")
+	nl := l.Attrs("key", "val")

 	nl.Info(ctx, "message")
 	if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) {
@ -49,7 +49,7 @@ func TestFromContextWithFields(t *testing.T) {
 	if err := l.Init(); err != nil {
 		t.Fatal(err)
 	}
-	nl := l.Fields("key", "val")
+	nl := l.Attrs("key", "val")

 	ctx = NewContext(ctx, nl)

@ -121,7 +121,7 @@ func TestLogger(t *testing.T) {
 	}
 	l.Trace(ctx, "trace_msg1")
 	l.Warn(ctx, "warn_msg1")
-	l.Fields("error", "test").Info(ctx, "error message")
+	l.Attrs("error", "test").Info(ctx, "error message")
 	l.Warn(ctx, "first second")

 	if !(bytes.Contains(buf.Bytes(), []byte(`"level":"trace"`)) && bytes.Contains(buf.Bytes(), []byte(`"msg":"trace_msg1"`))) {
--- a/logger/options.go
+++ b/logger/options.go
@ -4,8 +4,10 @@ import (
 	"context"
 	"io"
 	"os"
+	"reflect"

 	"go.unistack.org/micro/v4/options"
+	rutil "go.unistack.org/micro/v4/util/reflect"
 )

 // Options holds logger options
@ -14,24 +16,27 @@ type Options struct {
 	Out io.Writer
 	// Context holds exernal options
 	Context context.Context
-	// Fields holds additional metadata
-	Fields []interface{}
+	// Attrs holds additional attributes
+	Attrs []interface{}
 	// Name holds the logger name
 	Name string
 	// The logging level the logger should log
 	Level Level
 	// CallerSkipCount number of frmaes to skip
 	CallerSkipCount int
+	// ContextAttrFuncs contains funcs that executed before log func on context
+	ContextAttrFuncs []ContextAttrFunc
 }

 // NewOptions creates new options struct
 func NewOptions(opts ...options.Option) Options {
 	options := Options{
 		Level:            DefaultLevel,
-		Fields:          make([]interface{}, 0, 6),
+		Attrs:            make([]interface{}, 0, 6),
 		Out:              os.Stderr,
 		CallerSkipCount:  DefaultCallerSkipCount,
 		Context:          context.Background(),
+		ContextAttrFuncs: DefaultContextAttrFuncs,
 	}
 	for _, o := range opts {
 		o(&options)
@ -39,10 +44,27 @@ func NewOptions(opts ...options.Option) Options {
 	return options
 }

-// WithFields set default fields for the logger
-func WithFields(fields ...interface{}) options.Option {
+// WithContextAttrFuncs appends default funcs for the context arrts filler
+func WithContextAttrFuncs(attrs ...interface{}) options.Option {
 	return func(src interface{}) error {
-		return options.Set(src, fields, ".Fields")
+		v, err := options.Get(src, ".ContextAttrFuncs")
+		if err != nil {
+			return err
+		} else if rutil.IsZero(v) {
+			v = reflect.MakeSlice(reflect.TypeOf(v), 0, len(attrs)).Interface()
+		}
+		cv := reflect.ValueOf(v)
+		for _, l := range attrs {
+			cv = reflect.Append(cv, reflect.ValueOf(l))
+		}
+		return options.Set(src, cv.Interface(), ".ContextAttrFuncs")
+	}
+}
+
+// WithAttrs set default fields for the logger
+func WithAttrs(attrs ...interface{}) options.Option {
+	return func(src interface{}) error {
+		return options.Set(src, attrs, ".Attrs")
 	}
 }

--- a/logger/slog.go
+++ b/logger/slog.go
@ -26,9 +26,6 @@ var renameAttr = func(_ []string, a slog.Attr) slog.Attr {
 		source := a.Value.Any().(*slog.Source)
 		a.Value = slog.StringValue(source.File + ":" + strconv.Itoa(source.Line))
 		a.Key = "caller"
-		// add func?
-		// "trace": "<traceid>",
-		// "span": "<spanid>",
 	case slog.TimeKey:
 		a.Key = "timestamp"
 	case slog.LevelKey:
@ -85,7 +82,7 @@ func (s *slogLogger) Clone(opts ...options.Option) Logger {
 	}
 	l.leveler.Set(loggerToSlogLevel(l.opts.Level))
 	handler := slog.NewJSONHandler(options.Out, handleOpt)
-	l.slog = slog.New(handler).With(options.Fields...)
+	l.slog = slog.New(handler).With(options.Attrs...)

 	return l
 }
@ -102,7 +99,7 @@ func (s *slogLogger) Options() Options {
 	return s.opts
 }

-func (s *slogLogger) Fields(fields ...interface{}) Logger {
+func (s *slogLogger) Attrs(attrs ...interface{}) Logger {
 	nl := &slogLogger{opts: s.opts}
 	nl.leveler = new(slog.LevelVar)
 	nl.leveler.Set(s.leveler.Level())
@ -114,7 +111,7 @@ func (s *slogLogger) Fields(fields ...interface{}) Logger {
 	}

 	handler := slog.NewJSONHandler(s.opts.Out, handleOpt)
-	nl.slog = slog.New(handler).With(fields...)
+	nl.slog = slog.New(handler).With(attrs...)

 	return nl
 }
@ -139,86 +136,107 @@ func (s *slogLogger) Init(opts ...options.Option) error {
 	}
 	s.leveler.Set(loggerToSlogLevel(s.opts.Level))
 	handler := slog.NewJSONHandler(s.opts.Out, handleOpt)
-	s.slog = slog.New(handler).With(s.opts.Fields...)
+	s.slog = slog.New(handler).With(s.opts.Attrs...)

 	return nil
 }

-func (s *slogLogger) Log(ctx context.Context, lvl Level, msg string, args ...any) {
+func (s *slogLogger) Log(ctx context.Context, lvl Level, msg string, attrs ...interface{}) {
 	if !s.V(lvl) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), loggerToSlogLevel(lvl), msg, pcs[0])
-	r.Add(args...)
+	for _, fn := range s.opts.ContextAttrFuncs {
+		attrs = append(attrs, fn(ctx))
+	}
+	r.Add(attrs...)
 	_ = s.slog.Handler().Handle(ctx, r)
 }

-func (s *slogLogger) Info(ctx context.Context, msg string, args ...interface{}) {
+func (s *slogLogger) Info(ctx context.Context, msg string, attrs ...interface{}) {
 	if !s.V(InfoLevel) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), slog.LevelInfo, msg, pcs[0])
-	r.Add(args...)
+	for _, fn := range s.opts.ContextAttrFuncs {
+		attrs = append(attrs, fn(ctx))
+	}
+	r.Add(attrs...)
 	_ = s.slog.Handler().Handle(ctx, r)
 }

-func (s *slogLogger) Debug(ctx context.Context, msg string, args ...any) {
+func (s *slogLogger) Debug(ctx context.Context, msg string, attrs ...interface{}) {
 	if !s.V(InfoLevel) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), slog.LevelDebug, msg, pcs[0])
-	r.Add(args...)
+	for _, fn := range s.opts.ContextAttrFuncs {
+		attrs = append(attrs, fn(ctx))
+	}
+	r.Add(attrs...)
 	_ = s.slog.Handler().Handle(ctx, r)
 }

-func (s *slogLogger) Trace(ctx context.Context, msg string, args ...interface{}) {
+func (s *slogLogger) Trace(ctx context.Context, msg string, attrs ...interface{}) {
 	if !s.V(InfoLevel) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), slog.LevelDebug-1, msg, pcs[0])
-	r.Add(args...)
+	for _, fn := range s.opts.ContextAttrFuncs {
+		attrs = append(attrs, fn(ctx))
+	}
+	r.Add(attrs...)
 	_ = s.slog.Handler().Handle(ctx, r)
 }

-func (s *slogLogger) Error(ctx context.Context, msg string, args ...any) {
+func (s *slogLogger) Error(ctx context.Context, msg string, attrs ...interface{}) {
 	if !s.V(InfoLevel) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), slog.LevelError, msg, pcs[0])
-	r.Add(args...)
+	for _, fn := range s.opts.ContextAttrFuncs {
+		attrs = append(attrs, fn(ctx))
+	}
+	r.Add(attrs...)
 	_ = s.slog.Handler().Handle(ctx, r)
 }

-func (s *slogLogger) Fatal(ctx context.Context, msg string, args ...interface{}) {
+func (s *slogLogger) Fatal(ctx context.Context, msg string, attrs ...interface{}) {
 	if !s.V(InfoLevel) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), slog.LevelError+1, msg, pcs[0])
-	r.Add(args...)
+	for _, fn := range s.opts.ContextAttrFuncs {
+		attrs = append(attrs, fn(ctx))
+	}
+	r.Add(attrs...)
 	_ = s.slog.Handler().Handle(ctx, r)
 	os.Exit(1)
 }

-func (s *slogLogger) Warn(ctx context.Context, msg string, args ...any) {
+func (s *slogLogger) Warn(ctx context.Context, msg string, attrs ...interface{}) {
 	if !s.V(InfoLevel) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(s.opts.CallerSkipCount, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), slog.LevelWarn, msg, pcs[0])
-	r.Add(args...)
+	for _, fn := range s.opts.ContextAttrFuncs {
+		attrs = append(attrs, fn(ctx))
+	}
+	r.Add(attrs...)
 	_ = s.slog.Handler().Handle(ctx, r)
 }

--- a/tracer/noop.go
+++ b/tracer/noop.go
@ -4,6 +4,7 @@ import (
 	"context"

 	"go.unistack.org/micro/v4/options"
+	"go.unistack.org/micro/v4/util/id"
 )

 var _ Tracer = (*noopTracer)(nil)
@ -26,6 +27,8 @@ func (t *noopTracer) Start(ctx context.Context, name string, opts ...options.Opt
 		labels: options.Labels,
 		kind:   options.Kind,
 	}
+	span.spanID, _ = id.New()
+	span.traceID, _ = id.New()
 	if span.ctx == nil {
 		span.ctx = context.Background()
 	}
@ -63,6 +66,8 @@ type noopSpan struct {
 	logs      []interface{}
 	kind      SpanKind
 	status    SpanStatus
+	traceID   string
+	spanID    string
 }

 func (s *noopSpan) Finish(opts ...options.Option) {
@ -97,6 +102,14 @@ func (s *noopSpan) Kind() SpanKind {
 	return s.kind
 }

+func (s *noopSpan) TraceID() string {
+	return s.traceID
+}
+
+func (s *noopSpan) SpanID() string {
+	return s.spanID
+}
+
 func (s *noopSpan) Status() (SpanStatus, string) {
 	return s.status, s.statusMsg
 }
--- a/tracer/tracer.go
+++ b/tracer/tracer.go
@ -6,6 +6,7 @@ import (
 	"fmt"
 	"sort"

+	"go.unistack.org/micro/v4/logger"
 	"go.unistack.org/micro/v4/options"
 )

@ -45,6 +46,20 @@ type Span interface {
 	AddLogs(kv ...interface{})
 	// Kind returns span kind
 	Kind() SpanKind
+	// TraceID returns trace id
+	TraceID() string
+	// SpanID returns span id
+	SpanID() string
+}
+
+func init() {
+	logger.DefaultContextAttrFuncs = append(logger.DefaultContextAttrFuncs, func(ctx context.Context) []interface{} {
+		span, ok := SpanFromContext(ctx)
+		if !ok || span == nil {
+			return nil
+		}
+		return []interface{}{"trace", span.TraceID(), "span", span.SpanID()}
+	})
 }

 // sort labels alphabeticaly by label name