update slog/logger (#351)

Изменено (методы logger без форматирования):

- Добавлена подготовка и выравнивание аттрибутов для logger
- Выравнивание за счет добавления !BADKEY до процессинга log/slog
- Добавлено переиспользование метода Log
- Удалены методы [Logf, Infof, Debugf, Errorf, Warnf, Fatalf, Tracef]
- Обновлены юниттесты
- Удален wrapper в пакете logger
- Изменен интерфейс logger
- Отрефакторены вызовы logger'a в micro

Co-authored-by: Vasiliy Tolstov <v.tolstov@unistack.org>
Reviewed-on: #351
Co-authored-by: Evstigneev Denis <danteevstigneev@yandex.ru>
Co-committed-by: Evstigneev Denis <danteevstigneev@yandex.ru>
This commit is contained in:
Денис Евстигнеев 2024-10-12 12:37:43 +03:00 committed by Василий Толстов
parent 71fe0df73f
commit 59f9b65d3c
16 changed files with 209 additions and 982 deletions

View File

@ -206,7 +206,7 @@ func (m *memoryBroker) publish(ctx context.Context, msgs []*broker.Message, opts
} }
} else if sub.opts.AutoAck { } else if sub.opts.AutoAck {
if err = ms.Ack(); err != nil { if err = ms.Ack(); err != nil {
m.opts.Logger.Errorf(m.opts.Context, "ack failed: %v", err) m.opts.Logger.Error(m.opts.Context, "broker ack error", err)
} }
} }
// single processing // single processing
@ -217,11 +217,11 @@ func (m *memoryBroker) publish(ctx context.Context, msgs []*broker.Message, opts
if eh != nil { if eh != nil {
_ = eh(p) _ = eh(p)
} else if m.opts.Logger.V(logger.ErrorLevel) { } 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 { } else if sub.opts.AutoAck {
if err = p.Ack(); err != nil { if err = p.Ack(); err != nil {
m.opts.Logger.Errorf(m.opts.Context, "ack failed: %v", err) m.opts.Logger.Error(m.opts.Context, "broker ack error", err)
} }
} }
} }

View File

@ -4,6 +4,7 @@ package config
import ( import (
"context" "context"
"errors" "errors"
"fmt"
"reflect" "reflect"
"time" "time"
) )
@ -138,7 +139,7 @@ var (
return nil return nil
} }
if err := fn(ctx, c); err != 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 error", c.String()), err)
if !c.Options().AllowFail { if !c.Options().AllowFail {
return err return err
} }
@ -153,7 +154,7 @@ var (
return nil return nil
} }
if err := fn(ctx, c); err != 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 error", c.String()), err)
if !c.Options().AllowFail { if !c.Options().AllowFail {
return err return err
} }
@ -168,7 +169,7 @@ var (
return nil return nil
} }
if err := fn(ctx, c); err != 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 error", c.String()), err)
if !c.Options().AllowFail { if !c.Options().AllowFail {
return err return err
} }
@ -183,7 +184,7 @@ var (
return nil return nil
} }
if err := fn(ctx, c); err != 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 error", c.String()), err)
if !c.Options().AllowFail { if !c.Options().AllowFail {
return err return err
} }
@ -198,7 +199,7 @@ var (
return nil return nil
} }
if err := fn(ctx, c); err != 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 error", c.String()), err)
if !c.Options().AllowFail { if !c.Options().AllowFail {
return err return err
} }
@ -213,7 +214,7 @@ var (
return nil return nil
} }
if err := fn(ctx, c); err != 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 error", c.String(), err), err)
if !c.Options().AllowFail { if !c.Options().AllowFail {
return err return err
} }

View File

@ -188,7 +188,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu
steps, err := w.getSteps(options.Start, options.Reverse) steps, err := w.getSteps(options.Start, options.Reverse)
if err != nil { if err != nil {
if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusPending.String())}); werr != 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, "store write error", werr)
} }
return "", err return "", err
} }
@ -212,7 +212,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu
done := make(chan struct{}) done := make(chan struct{})
if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusRunning.String())}); werr != nil { 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, "store write error", werr)
return eid, werr return eid, werr
} }
for idx := range steps { for idx := range steps {
@ -237,7 +237,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu
return return
} }
if w.opts.Logger.V(logger.TraceLevel) { 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] cstep := steps[idx][nidx]
// nolint: nestif // nolint: nestif
@ -257,21 +257,21 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu
if serr != nil { if serr != nil {
step.SetStatus(StatusFailure) 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) { 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, "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) { 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, "store write error", werr)
} }
cherr <- serr cherr <- serr
return return
} }
if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"rsp", rsp); werr != nil { 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, "store write error", werr)
cherr <- werr cherr <- werr
return return
} }
if werr := stepStore.Write(ctx, step.ID()+w.opts.Store.Options().Separator+"status", &codec.Frame{Data: []byte(StatusSuccess.String())}); werr != nil { 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, "store write error", werr)
cherr <- werr cherr <- werr
return return
} }
@ -290,16 +290,16 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu
if serr != nil { if serr != nil {
cstep.SetStatus(StatusFailure) 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) { 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, "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) { 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, "store write error", werr)
} }
cherr <- serr cherr <- serr
return return
} }
if werr := stepStore.Write(ctx, cstep.ID()+w.opts.Store.Options().Separator+"rsp", rsp); werr != nil { 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, "store write error", werr)
cherr <- werr cherr <- werr
return return
} }
@ -317,7 +317,7 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu
return eid, nil return eid, nil
} }
logger.Tracef(ctx, "wait for finish or error") logger.DefaultLogger.Trace(ctx, "wait for finish or error")
select { select {
case <-nctx.Done(): case <-nctx.Done():
err = nctx.Err() err = nctx.Err()
@ -333,15 +333,15 @@ func (w *microWorkflow) Execute(ctx context.Context, req *Message, opts ...Execu
switch { switch {
case nctx.Err() != nil: case nctx.Err() != nil:
if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusAborted.String())}); werr != 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, "store write error", werr)
} }
case err == nil: case err == nil:
if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusSuccess.String())}); werr != 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, "store write error", werr)
} }
case err != nil: case err != nil:
if werr := workflowStore.Write(w.opts.Context, "status", &codec.Frame{Data: []byte(StatusFailure.String())}); werr != 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, "store write error", werr)
} }
} }

View File

@ -17,7 +17,7 @@ func TestFSMStart(t *testing.T) {
wrapper := func(next StateFunc) StateFunc { wrapper := func(next StateFunc) StateFunc {
return func(sctx context.Context, s State, opts ...StateOption) (State, error) { 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...) return next(sctx, s, opts...)
} }
} }

View File

@ -14,8 +14,6 @@ var (
DefaultLogger Logger = NewLogger() DefaultLogger Logger = NewLogger()
// DefaultLevel used by logger // DefaultLevel used by logger
DefaultLevel = InfoLevel DefaultLevel = InfoLevel
// DefaultCallerSkipCount used by logger
DefaultCallerSkipCount = 2
) )
// Logger is a generic logging interface // Logger is a generic logging interface
@ -33,33 +31,19 @@ type Logger interface {
// Fields set fields to always be logged with keyval pairs // Fields set fields to always be logged with keyval pairs
Fields(fields ...interface{}) Logger Fields(fields ...interface{}) Logger
// Info level message // Info level message
Info(ctx context.Context, args ...interface{}) Info(ctx context.Context, msg string, args ...interface{})
// Trace level message // Trace level message
Trace(ctx context.Context, args ...interface{}) Trace(ctx context.Context, msg string, args ...interface{})
// Debug level message // Debug level message
Debug(ctx context.Context, args ...interface{}) Debug(ctx context.Context, msg string, args ...interface{})
// Warn level message // Warn level message
Warn(ctx context.Context, args ...interface{}) Warn(ctx context.Context, msg string, args ...interface{})
// Error level message // Error level message
Error(ctx context.Context, args ...interface{}) Error(ctx context.Context, msg string, args ...interface{})
// Fatal level message // Fatal level message
Fatal(ctx context.Context, args ...interface{}) Fatal(ctx context.Context, msg string, args ...interface{})
// Infof level message
Infof(ctx context.Context, msg string, args ...interface{})
// Tracef level message
Tracef(ctx context.Context, msg string, args ...interface{})
// Debug level message
Debugf(ctx context.Context, msg string, args ...interface{})
// Warn level message
Warnf(ctx context.Context, msg string, args ...interface{})
// Error level message
Errorf(ctx context.Context, msg string, args ...interface{})
// Fatal level message
Fatalf(ctx context.Context, msg string, args ...interface{})
// Log logs message with needed level // Log logs message with needed level
Log(ctx context.Context, level Level, args ...interface{}) Log(ctx context.Context, level Level, msg string, args ...interface{})
// Logf logs message with needed level
Logf(ctx context.Context, level Level, msg string, args ...interface{})
// Name returns broker instance name // Name returns broker instance name
Name() string Name() string
// String returns the type of logger // String returns the type of logger
@ -68,108 +52,3 @@ type Logger interface {
// Field contains keyval pair // Field contains keyval pair
type Field interface{} 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...)
}

View File

@ -4,12 +4,17 @@ import (
"context" "context"
) )
const (
defaultCallerSkipCount = 2
)
type noopLogger struct { type noopLogger struct {
opts Options opts Options
} }
func NewLogger(opts ...Option) Logger { func NewLogger(opts ...Option) Logger {
options := NewOptions(opts...) options := NewOptions(opts...)
options.CallerSkipCount = defaultCallerSkipCount
return &noopLogger{opts: options} return &noopLogger{opts: options}
} }
@ -51,44 +56,23 @@ func (l *noopLogger) String() string {
return "noop" 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{}) {
}
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{}) {
} }

View File

@ -23,7 +23,7 @@ type Options struct {
Name string Name string
// Fields holds additional metadata // Fields holds additional metadata
Fields []interface{} Fields []interface{}
// CallerSkipCount number of frmaes to skip // callerSkipCount number of frmaes to skip
CallerSkipCount int CallerSkipCount int
// ContextAttrFuncs contains funcs that executed before log func on context // ContextAttrFuncs contains funcs that executed before log func on context
ContextAttrFuncs []ContextAttrFunc ContextAttrFuncs []ContextAttrFunc
@ -57,7 +57,6 @@ func NewOptions(opts ...Option) Options {
Level: DefaultLevel, Level: DefaultLevel,
Fields: make([]interface{}, 0, 6), Fields: make([]interface{}, 0, 6),
Out: os.Stderr, Out: os.Stderr,
CallerSkipCount: DefaultCallerSkipCount,
Context: context.Background(), Context: context.Background(),
ContextAttrFuncs: DefaultContextAttrFuncs, ContextAttrFuncs: DefaultContextAttrFuncs,
AddSource: true, AddSource: true,
@ -102,27 +101,20 @@ func WithOutput(out io.Writer) Option {
} }
} }
// WitAddStacktrace controls writing stacktrace on error // WithAddStacktrace controls writing stacktrace on error
func WithAddStacktrace(v bool) Option { func WithAddStacktrace(v bool) Option {
return func(o *Options) { return func(o *Options) {
o.AddStacktrace = v 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 { func WithAddSource(v bool) Option {
return func(o *Options) { return func(o *Options) {
o.AddSource = v o.AddSource = v
} }
} }
// WithCallerSkipCount set frame count to skip
func WithCallerSkipCount(c int) Option {
return func(o *Options) {
o.CallerSkipCount = c
}
}
// WithContext set context // WithContext set context
func WithContext(ctx context.Context) Option { func WithContext(ctx context.Context) Option {
return func(o *Options) { return func(o *Options) {
@ -198,6 +190,8 @@ func WithMicroKeys() Option {
// WithAddCallerSkipCount add skip count for copy logger // WithAddCallerSkipCount add skip count for copy logger
func WithAddCallerSkipCount(n int) Option { func WithAddCallerSkipCount(n int) Option {
return func(o *Options) { return func(o *Options) {
if n > 0 {
o.CallerSkipCount += n o.CallerSkipCount += n
} }
}
} }

View File

@ -2,7 +2,6 @@ package slog
import ( import (
"context" "context"
"fmt"
"log/slog" "log/slog"
"os" "os"
"regexp" "regexp"
@ -15,6 +14,12 @@ import (
"go.unistack.org/micro/v3/tracer" "go.unistack.org/micro/v3/tracer"
) )
const (
badKey = "!BADKEY"
// defaultCallerSkipCount used by logger
defaultCallerSkipCount = 3
)
var reTrace = regexp.MustCompile(`.*/slog/logger\.go.*\n`) var reTrace = regexp.MustCompile(`.*/slog/logger\.go.*\n`)
var ( var (
@ -150,386 +155,33 @@ func (s *slogLogger) Init(opts ...logger.Option) error {
return nil return nil
} }
func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, attrs ...interface{}) { func (s *slogLogger) Log(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) {
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() s.printLog(ctx, lvl, msg, attrs...)
if !s.V(lvl) {
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)...)
}
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) Logf(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) { func (s *slogLogger) Info(ctx context.Context, msg string, attrs ...interface{}) {
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc() s.printLog(ctx, logger.InfoLevel, msg, attrs...)
if !s.V(lvl) {
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{}) { func (s *slogLogger) Debug(ctx context.Context, msg string, attrs ...interface{}) {
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.InfoLevel.String()).Inc() s.printLog(ctx, logger.DebugLevel, msg, attrs...)
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)
} }
func (s *slogLogger) Infof(ctx context.Context, msg string, attrs ...interface{}) { func (s *slogLogger) Trace(ctx context.Context, msg string, attrs ...interface{}) {
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.InfoLevel.String()).Inc() s.printLog(ctx, logger.TraceLevel, msg, attrs...)
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, 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{}) { func (s *slogLogger) Error(ctx context.Context, msg string, attrs ...interface{}) {
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.DebugLevel.String()).Inc() s.printLog(ctx, logger.ErrorLevel, msg, attrs...)
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)
} }
func (s *slogLogger) Debugf(ctx context.Context, msg string, attrs ...interface{}) { func (s *slogLogger) Fatal(ctx context.Context, msg string, attrs ...interface{}) {
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.DebugLevel.String()).Inc() s.printLog(ctx, logger.FatalLevel, msg, attrs...)
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, 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.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)
}
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) {
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.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)
}
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) {
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.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)
os.Exit(1) os.Exit(1)
} }
func (s *slogLogger) Fatalf(ctx context.Context, msg string, attrs ...interface{}) { func (s *slogLogger) Warn(ctx context.Context, msg string, attrs ...interface{}) {
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", logger.FatalLevel.String()).Inc() s.printLog(ctx, logger.WarnLevel, msg, attrs...)
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, 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.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)
}
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) {
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 { func (s *slogLogger) Name() string {
@ -540,10 +192,52 @@ func (s *slogLogger) String() string {
return "slog" return "slog"
} }
func (s *slogLogger) printLog(ctx context.Context, lvl logger.Level, msg string, attrs ...interface{}) {
if !s.V(lvl) {
return
}
s.opts.Meter.Counter(semconv.LoggerMessageTotal, "level", lvl.String()).Inc()
attrs = prepareAttributes(attrs)
for _, fn := range s.opts.ContextAttrFuncs {
a := prepareAttributes(fn(ctx))
attrs = append(attrs, a...)
}
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
}
}
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]))
}
}
}
var pcs [1]uintptr
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)
}
func NewLogger(opts ...logger.Option) logger.Logger { func NewLogger(opts ...logger.Option) logger.Logger {
s := &slogLogger{ s := &slogLogger{
opts: logger.NewOptions(opts...), opts: logger.NewOptions(opts...),
} }
s.opts.CallerSkipCount = defaultCallerSkipCount
return s return s
} }
@ -581,3 +275,12 @@ func slogToLoggerLevel(level slog.Level) logger.Level {
return logger.InfoLevel 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
}

View File

@ -3,8 +3,12 @@ package slog
import ( import (
"bytes" "bytes"
"context" "context"
"errors"
"fmt" "fmt"
"github.com/google/uuid"
"go.unistack.org/micro/v3/metadata"
"log" "log"
"strings"
"testing" "testing"
"go.unistack.org/micro/v3/logger" "go.unistack.org/micro/v3/logger"
@ -29,13 +33,25 @@ func TestError(t *testing.T) {
func TestErrorf(t *testing.T) { func TestErrorf(t *testing.T) {
ctx := context.TODO() ctx := context.TODO()
buf := bytes.NewBuffer(nil) buf := bytes.NewBuffer(nil)
l := NewLogger(logger.WithLevel(logger.ErrorLevel), logger.WithOutput(buf), logger.WithAddStacktrace(true)) 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) 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":"`)) { if !bytes.Contains(buf.Bytes(), []byte(`"stacktrace":"`)) {
t.Fatalf("logger stacktrace not works, buf contains: %s", buf.Bytes()) t.Fatalf("logger stacktrace not works, buf contains: %s", buf.Bytes())
} }
@ -99,6 +115,11 @@ func TestFromContextWithFields(t *testing.T) {
if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) { if !bytes.Contains(buf.Bytes(), []byte(`"key":"val"`)) {
t.Fatalf("logger fields not works, buf contains: %s", buf.Bytes()) 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) { func TestClone(t *testing.T) {
@ -174,3 +195,46 @@ func TestLogger(t *testing.T) {
t.Fatalf("logger warn, buf %s", buf.Bytes()) 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())
}
}

View File

@ -1,399 +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 []string
for _, o := range l.opts.ClientCallObservers {
labels = append(labels, o(ctx, req, rsp, opts, err)...)
}
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 []string
for _, o := range l.opts.ClientStreamObservers {
labels = append(labels, o(ctx, req, opts, stream, err)...)
}
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 []string
for _, o := range l.opts.ClientPublishObservers {
labels = append(labels, o(ctx, msg, opts, err)...)
}
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 []string
for _, o := range l.opts.ServerHandlerObservers {
labels = append(labels, o(ctx, req, rsp, err)...)
}
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 []string
for _, o := range l.opts.ServerSubscriberObservers {
labels = append(labels, o(ctx, msg, err)...)
}
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 []string
for _, o := range l.opts.ClientCallFuncObservers {
labels = append(labels, o(ctx, addr, req, rsp, opts, err)...)
}
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
}
}

View File

@ -177,12 +177,12 @@ func (t *tunBatchSubscriber) run() {
// receive message // receive message
m := new(transport.Message) m := new(transport.Message)
if err := c.Recv(m); err != nil { if err := c.Recv(m); err != nil {
if logger.V(logger.ErrorLevel) { if logger.DefaultLogger.V(logger.ErrorLevel) {
logger.Error(t.opts.Context, err.Error()) logger.DefaultLogger.Error(t.opts.Context, err.Error(), err)
} }
if err = c.Close(); err != nil { if err = c.Close(); err != nil {
if logger.V(logger.ErrorLevel) { if logger.DefaultLogger.V(logger.ErrorLevel) {
logger.Error(t.opts.Context, err.Error()) logger.DefaultLogger.Error(t.opts.Context, err.Error(), err)
} }
} }
continue continue
@ -222,12 +222,12 @@ func (t *tunSubscriber) run() {
// receive message // receive message
m := new(transport.Message) m := new(transport.Message)
if err := c.Recv(m); err != nil { if err := c.Recv(m); err != nil {
if logger.V(logger.ErrorLevel) { if logger.DefaultLogger.V(logger.ErrorLevel) {
logger.Error(t.opts.Context, err.Error()) logger.DefaultLogger.Error(t.opts.Context, err.Error(), err)
} }
if err = c.Close(); err != nil { if err = c.Close(); err != nil {
if logger.V(logger.ErrorLevel) { if logger.DefaultLogger.V(logger.ErrorLevel) {
logger.Error(t.opts.Context, err.Error()) logger.DefaultLogger.Error(t.opts.Context, err.Error(), err)
} }
} }
continue continue

View File

@ -2,6 +2,7 @@ package register
import ( import (
"context" "context"
"fmt"
"sync" "sync"
"time" "time"
@ -64,7 +65,7 @@ func (m *memory) ttlPrune() {
for id, n := range record.Nodes { for id, n := range record.Nodes {
if n.TTL != 0 && time.Since(n.LastSeen) > n.TTL { if n.TTL != 0 && time.Since(n.LastSeen) > n.TTL {
if m.opts.Logger.V(logger.DebugLevel) { 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) 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 { if _, ok := srvs[s.Name][s.Version]; !ok {
srvs[s.Name][s.Version] = r srvs[s.Name][s.Version] = r
if m.opts.Logger.V(logger.DebugLevel) { 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 m.records[options.Domain] = srvs
go m.sendEvent(&register.Result{Action: "create", Service: s}) go m.sendEvent(&register.Result{Action: "create", Service: s})
@ -191,14 +192,14 @@ func (m *memory) Register(ctx context.Context, s *register.Service, opts ...regi
if addedNodes { if addedNodes {
if m.opts.Logger.V(logger.DebugLevel) { 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(&register.Result{Action: "update", Service: s}) go m.sendEvent(&register.Result{Action: "update", Service: s})
} else { } else {
// refresh TTL and timestamp // refresh TTL and timestamp
for _, n := range s.Nodes { for _, n := range s.Nodes {
if m.opts.Logger.V(logger.DebugLevel) { 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].TTL = options.TTL
srvs[s.Name][s.Version].Nodes[n.ID].LastSeen = time.Now() 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 { for _, n := range s.Nodes {
if _, ok := version.Nodes[n.ID]; ok { if _, ok := version.Nodes[n.ID]; ok {
if m.opts.Logger.V(logger.DebugLevel) { 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) delete(version.Nodes, n.ID)
} }
@ -264,7 +265,7 @@ func (m *memory) Deregister(ctx context.Context, s *register.Service, opts ...re
go m.sendEvent(&register.Result{Action: "delete", Service: s}) go m.sendEvent(&register.Result{Action: "delete", Service: s})
if m.opts.Logger.V(logger.DebugLevel) { 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 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) delete(m.records[options.Domain][s.Name], s.Version)
go m.sendEvent(&register.Result{Action: "delete", Service: s}) go m.sendEvent(&register.Result{Action: "delete", Service: s})
if m.opts.Logger.V(logger.DebugLevel) { 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 return nil

View File

@ -459,7 +459,7 @@ func (n *noopServer) Start() error {
} }
} else if rerr != nil && !registered { } else if rerr != nil && !registered {
if config.Logger.V(logger.ErrorLevel) { 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 continue
} }

View File

@ -276,7 +276,7 @@ func (s *service) Start() error {
} }
if config.Loggers[0].V(logger.InfoLevel) { 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 { if len(s.opts.Servers) == 0 {
@ -322,7 +322,7 @@ func (s *service) Stop() error {
s.RUnlock() s.RUnlock()
if config.Loggers[0].V(logger.InfoLevel) { 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 var err error

View File

@ -17,14 +17,14 @@ func TestLoggerWithTracer(t *testing.T) {
buf := bytes.NewBuffer(nil) buf := bytes.NewBuffer(nil)
logger.DefaultLogger = slog.NewLogger(logger.WithOutput(buf)) logger.DefaultLogger = slog.NewLogger(logger.WithOutput(buf))
if err := logger.Init(); err != nil { if err := logger.DefaultLogger.Init(); err != nil {
t.Fatal(err) t.Fatal(err)
} }
var span tracer.Span var span tracer.Span
tr := NewTracer() tr := NewTracer()
ctx, span = tr.Start(ctx, "test1") 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()) { if !strings.Contains(buf.String(), span.TraceID()) {
t.Fatalf("log does not contains trace id: %s", buf.Bytes()) t.Fatalf("log does not contains trace id: %s", buf.Bytes())

View File

@ -71,7 +71,7 @@ func New(opts ...Option) (string, error) {
func Must(opts ...Option) string { func Must(opts ...Option) string {
id, err := New(opts...) id, err := New(opts...)
if err != nil { if err != nil {
logger.Fatal(context.TODO(), err) logger.DefaultLogger.Fatal(context.TODO(), "Must call is failed", err)
} }
return id return id
} }