From cf0b39eaacb8f3323e2e85c9784f9347000746eb Mon Sep 17 00:00:00 2001 From: Vasiliy Tolstov Date: Mon, 24 Feb 2020 16:07:40 +0300 Subject: [PATCH] logger fixes (#1244) * logger: fix race conditions Signed-off-by: Vasiliy Tolstov * restore util/log for compatibility Signed-off-by: Vasiliy Tolstov --- logger/default.go | 39 ++++++-- util/log/README.md | 17 ++++ util/log/log.go | 227 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 275 insertions(+), 8 deletions(-) create mode 100644 util/log/README.md create mode 100644 util/log/log.go diff --git a/logger/default.go b/logger/default.go index 3369f64e..6fa2b009 100644 --- a/logger/default.go +++ b/logger/default.go @@ -4,12 +4,14 @@ import ( "context" "fmt" "os" + "sync" "time" dlog "github.com/micro/go-micro/v2/debug/log" ) type defaultLogger struct { + sync.RWMutex opts Options err error } @@ -27,31 +29,46 @@ func (l *defaultLogger) String() string { } func (l *defaultLogger) Fields(fields map[string]interface{}) Logger { - l.opts.Fields = fields + l.Lock() + l.opts.Fields = copyFields(fields) + l.Unlock() return l } func (l *defaultLogger) Error(err error) Logger { + l.Lock() l.err = err + l.Unlock() return l } +func copyFields(src map[string]interface{}) map[string]interface{} { + dst := make(map[string]interface{}, len(src)) + for k, v := range src { + dst[k] = v + } + return dst +} + func (l *defaultLogger) Log(level Level, v ...interface{}) { // TODO decide does we need to write message if log level not used? if !l.opts.Level.Enabled(level) { return } - fields := l.opts.Fields - fields["level"] = level.String() + l.RLock() + fields := copyFields(l.opts.Fields) if l.err != nil { fields["error"] = l.err.Error() } + l.RUnlock() + + fields["level"] = level.String() rec := dlog.Record{ Timestamp: time.Now(), Message: fmt.Sprint(v...), - Metadata: make(map[string]string), + Metadata: make(map[string]string, len(fields)), } for k, v := range fields { rec.Metadata[k] = fmt.Sprintf("%v", v) @@ -69,16 +86,19 @@ func (l *defaultLogger) Logf(level Level, format string, v ...interface{}) { return } - fields := l.opts.Fields - fields["level"] = level.String() + l.RLock() + fields := copyFields(l.opts.Fields) if l.err != nil { fields["error"] = l.err.Error() } + l.RUnlock() + + fields["level"] = level.String() rec := dlog.Record{ Timestamp: time.Now(), Message: fmt.Sprintf(format, v...), - Metadata: make(map[string]string), + Metadata: make(map[string]string, len(fields)), } for k, v := range fields { rec.Metadata[k] = fmt.Sprintf("%v", v) @@ -105,6 +125,9 @@ func NewLogger(opts ...Option) Logger { } l := &defaultLogger{opts: options} - _ = l.Init(opts...) + if err := l.Init(opts...); err != nil { + l.Log(FatalLevel, err) + } + return l } diff --git a/util/log/README.md b/util/log/README.md new file mode 100644 index 00000000..97ddacf3 --- /dev/null +++ b/util/log/README.md @@ -0,0 +1,17 @@ +# Log + +DEPRECATED: use github.com/micro/go-micro/v2/logger interface + +This is the global logger for all micro based libraries. + +## Set Logger + +Set the logger for micro libraries + +```go +// import go-micro/util/log +import "github.com/micro/go-micro/util/log" + +// SetLogger expects github.com/micro/go-micro/debug/log.Log interface +log.SetLogger(mylogger) +``` diff --git a/util/log/log.go b/util/log/log.go new file mode 100644 index 00000000..16e5cd83 --- /dev/null +++ b/util/log/log.go @@ -0,0 +1,227 @@ +// Package log is a global internal logger +// DEPRECATED: this is frozen package, use github.com/micro/go-micro/v2/logger +package log + +import ( + "fmt" + "os" + "sync/atomic" + + dlog "github.com/micro/go-micro/v2/debug/log" + nlog "github.com/micro/go-micro/v2/logger" +) + +// level is a log level +type Level int32 + +const ( + LevelFatal Level = iota + LevelError + LevelWarn + LevelInfo + LevelDebug + LevelTrace +) + +type elog struct { + dlog dlog.Log +} + +var ( + // the local logger + logger dlog.Log = &elog{} + + // default log level is info + level = LevelInfo + + // prefix for all messages + prefix string +) + +func levelToLevel(l Level) nlog.Level { + switch l { + case LevelTrace: + return nlog.TraceLevel + case LevelDebug: + return nlog.DebugLevel + case LevelWarn: + return nlog.WarnLevel + case LevelInfo: + return nlog.InfoLevel + case LevelError: + return nlog.ErrorLevel + case LevelFatal: + return nlog.FatalLevel + } + return nlog.InfoLevel +} + +func init() { + switch os.Getenv("MICRO_LOG_LEVEL") { + case "trace": + level = LevelTrace + case "debug": + level = LevelDebug + case "warn": + level = LevelWarn + case "info": + level = LevelInfo + case "error": + level = LevelError + case "fatal": + level = LevelFatal + } +} + +func (l Level) String() string { + switch l { + case LevelTrace: + return "trace" + case LevelDebug: + return "debug" + case LevelWarn: + return "warn" + case LevelInfo: + return "info" + case LevelError: + return "error" + case LevelFatal: + return "fatal" + default: + return "unknown" + } +} + +func (el *elog) Read(opt ...dlog.ReadOption) ([]dlog.Record, error) { + return el.dlog.Read(opt...) +} + +func (el *elog) Write(r dlog.Record) error { + return el.dlog.Write(r) +} + +func (el *elog) Stream() (dlog.Stream, error) { + return el.dlog.Stream() +} + +// Log makes use of github.com/micro/debug/log +func Log(v ...interface{}) { + if len(prefix) > 0 { + v = append([]interface{}{prefix, " "}, v...) + } + nlog.DefaultLogger.Log(levelToLevel(level), v) +} + +// Logf makes use of github.com/micro/debug/log +func Logf(format string, v ...interface{}) { + if len(prefix) > 0 { + format = prefix + " " + format + } + nlog.DefaultLogger.Log(levelToLevel(level), format, v) +} + +// WithLevel logs with the level specified +func WithLevel(l Level, v ...interface{}) { + if l > level { + return + } + Log(v...) +} + +// WithLevel logs with the level specified +func WithLevelf(l Level, format string, v ...interface{}) { + if l > level { + return + } + Logf(format, v...) +} + +// Trace provides trace level logging +func Trace(v ...interface{}) { + WithLevel(LevelTrace, v...) +} + +// Tracef provides trace level logging +func Tracef(format string, v ...interface{}) { + WithLevelf(LevelTrace, format, v...) +} + +// Debug provides debug level logging +func Debug(v ...interface{}) { + WithLevel(LevelDebug, v...) +} + +// Debugf provides debug level logging +func Debugf(format string, v ...interface{}) { + WithLevelf(LevelDebug, format, v...) +} + +// Warn provides warn level logging +func Warn(v ...interface{}) { + WithLevel(LevelWarn, v...) +} + +// Warnf provides warn level logging +func Warnf(format string, v ...interface{}) { + WithLevelf(LevelWarn, format, v...) +} + +// Info provides info level logging +func Info(v ...interface{}) { + WithLevel(LevelInfo, v...) +} + +// Infof provides info level logging +func Infof(format string, v ...interface{}) { + WithLevelf(LevelInfo, format, v...) +} + +// Error provides warn level logging +func Error(v ...interface{}) { + WithLevel(LevelError, v...) +} + +// Errorf provides warn level logging +func Errorf(format string, v ...interface{}) { + WithLevelf(LevelError, format, v...) +} + +// Fatal logs with Log and then exits with os.Exit(1) +func Fatal(v ...interface{}) { + WithLevel(LevelFatal, v...) +} + +// Fatalf logs with Logf and then exits with os.Exit(1) +func Fatalf(format string, v ...interface{}) { + WithLevelf(LevelFatal, format, v...) +} + +// SetLogger sets the local logger +func SetLogger(l dlog.Log) { + logger = l +} + +// GetLogger returns the local logger +func GetLogger() dlog.Log { + return logger +} + +// SetLevel sets the log level +func SetLevel(l Level) { + atomic.StoreInt32((*int32)(&level), int32(l)) +} + +// GetLevel returns the current level +func GetLevel() Level { + return level +} + +// Set a prefix for the logger +func SetPrefix(p string) { + prefix = p +} + +// Set service name +func Name(name string) { + prefix = fmt.Sprintf("[%s]", name) +}