From 7568779db4c957d228e88cef19253b1b10682ebf Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Mon, 16 Oct 2023 23:43:39 +0300 Subject: [PATCH] logger: add ability to fill fileds from context Signed-off-by: Vasiliy Tolstov --- logger/logger.go | 57 ++++++++++++++++++++-------------------- logger/logger_test.go | 10 ++++---- logger/options.go | 42 ++++++++++++++++++++++-------- logger/slog.go | 60 ++++++++++++++++++++++++++++--------------- tracer/noop.go | 13 ++++++++++ tracer/tracer.go | 15 +++++++++++ 6 files changed, 133 insertions(+), 64 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 59a9c80b..3ef835a5 100644 --- 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...) } diff --git a/logger/logger_test.go b/logger/logger_test.go index 68f1508d..0d4d579b 100644 --- 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"`))) { diff --git a/logger/options.go b/logger/options.go index ce68ccca..f9a8dbcd 100644 --- 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), - Out: os.Stderr, - CallerSkipCount: DefaultCallerSkipCount, - Context: context.Background(), + Level: DefaultLevel, + 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") } } diff --git a/logger/slog.go b/logger/slog.go index df7b3634..fd1d2f80 100644 --- 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": "", - // "span": "", 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) } diff --git a/tracer/noop.go b/tracer/noop.go index 7fd2cc0a..3e293ce6 100644 --- 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 } diff --git a/tracer/tracer.go b/tracer/tracer.go index 387cdee5..db61567a 100644 --- 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