From 3323b886f1b8d4e1dcf49be6cb47f60cab3eb900 Mon Sep 17 00:00:00 2001 From: John Tzikas Date: Wed, 25 Nov 2020 12:30:42 +0200 Subject: [PATCH] Make mlogger atomic (#16398) * Make mlogger atomic * Apply PR suggestions * Fix logger initialization on testing * Apply PR suggestions --- mlog/log.go | 75 +++++++++++++++++++++++++++++------------------- mlog/log_test.go | 50 ++++++++++++++++++++++++++++++++ mlog/testing.go | 2 ++ 3 files changed, 98 insertions(+), 29 deletions(-) create mode 100644 mlog/log_test.go diff --git a/mlog/log.go b/mlog/log.go index eaa8c10948..6395240a1d 100644 --- a/mlog/log.go +++ b/mlog/log.go @@ -9,6 +9,7 @@ import ( "io" "log" "os" + "sync" "sync/atomic" "time" @@ -73,6 +74,7 @@ type Logger struct { consoleLevel zap.AtomicLevel fileLevel zap.AtomicLevel logrLogger *logr.Logger + mutex *sync.RWMutex } func getZapLevel(level string) zapcore.Level { @@ -106,6 +108,7 @@ func NewLogger(config *LoggerConfiguration) *Logger { consoleLevel: zap.NewAtomicLevelAt(getZapLevel(config.ConsoleLevel)), fileLevel: zap.NewAtomicLevelAt(getZapLevel(config.FileLevel)), logrLogger: newLogr(), + mutex: &sync.RWMutex{}, } if config.EnableConsole { @@ -162,13 +165,13 @@ func (l *Logger) SetConsoleLevel(level string) { } func (l *Logger) With(fields ...Field) *Logger { - newlogger := *l - newlogger.zap = newlogger.zap.With(fields...) - if newlogger.logrLogger != nil { - ll := newlogger.logrLogger.WithFields(zapToLogr(fields)) - newlogger.logrLogger = &ll + newLogger := *l + newLogger.zap = newLogger.zap.With(fields...) + if newLogger.getLogger() != nil { + ll := newLogger.getLogger().WithFields(zapToLogr(fields)) + newLogger.logrLogger = &ll } - return &newlogger + return &newLogger } func (l *Logger) StdLog(fields ...Field) *log.Logger { @@ -190,9 +193,9 @@ func (l *Logger) StdLogWriter() io.Writer { } func (l *Logger) WithCallerSkip(skip int) *Logger { - newlogger := *l - newlogger.zap = newlogger.zap.WithOptions(zap.AddCallerSkip(skip)) - return &newlogger + newLogger := *l + newLogger.zap = newLogger.zap.WithOptions(zap.AddCallerSkip(skip)) + return &newLogger } // Made for the plugin interface, wraps mlog in a simpler interface @@ -206,50 +209,50 @@ func (l *Logger) Sugar() *SugarLogger { func (l *Logger) Debug(message string, fields ...Field) { l.zap.Debug(message, fields...) - if isLevelEnabled(l.logrLogger, logr.Debug) { - l.logrLogger.WithFields(zapToLogr(fields)).Debug(message) + if isLevelEnabled(l.getLogger(), logr.Debug) { + l.getLogger().WithFields(zapToLogr(fields)).Debug(message) } } func (l *Logger) Info(message string, fields ...Field) { l.zap.Info(message, fields...) - if isLevelEnabled(l.logrLogger, logr.Info) { - l.logrLogger.WithFields(zapToLogr(fields)).Info(message) + if isLevelEnabled(l.getLogger(), logr.Info) { + l.getLogger().WithFields(zapToLogr(fields)).Info(message) } } func (l *Logger) Warn(message string, fields ...Field) { l.zap.Warn(message, fields...) - if isLevelEnabled(l.logrLogger, logr.Warn) { - l.logrLogger.WithFields(zapToLogr(fields)).Warn(message) + if isLevelEnabled(l.getLogger(), logr.Warn) { + l.getLogger().WithFields(zapToLogr(fields)).Warn(message) } } func (l *Logger) Error(message string, fields ...Field) { l.zap.Error(message, fields...) - if isLevelEnabled(l.logrLogger, logr.Error) { - l.logrLogger.WithFields(zapToLogr(fields)).Error(message) + if isLevelEnabled(l.getLogger(), logr.Error) { + l.getLogger().WithFields(zapToLogr(fields)).Error(message) } } func (l *Logger) Critical(message string, fields ...Field) { l.zap.Error(message, fields...) - if isLevelEnabled(l.logrLogger, logr.Error) { - l.logrLogger.WithFields(zapToLogr(fields)).Error(message) + if isLevelEnabled(l.getLogger(), logr.Error) { + l.getLogger().WithFields(zapToLogr(fields)).Error(message) } } func (l *Logger) Log(level LogLevel, message string, fields ...Field) { - l.logrLogger.WithFields(zapToLogr(fields)).Log(logr.Level(level), message) + l.getLogger().WithFields(zapToLogr(fields)).Log(logr.Level(level), message) } func (l *Logger) LogM(levels []LogLevel, message string, fields ...Field) { var logger *logr.Logger for _, lvl := range levels { - if isLevelEnabled(l.logrLogger, logr.Level(lvl)) { + if isLevelEnabled(l.getLogger(), logr.Level(lvl)) { // don't create logger with fields unless at least one level is active. if logger == nil { - l := l.logrLogger.WithFields(zapToLogr(fields)) + l := l.getLogger().WithFields(zapToLogr(fields)) logger = &l } logger.Log(logr.Level(lvl), message) @@ -258,15 +261,15 @@ func (l *Logger) LogM(levels []LogLevel, message string, fields ...Field) { } func (l *Logger) Flush(cxt context.Context) error { - return l.logrLogger.Logr().FlushWithTimeout(cxt) + return l.getLogger().Logr().FlushWithTimeout(cxt) } // ShutdownAdvancedLogging stops the logger from accepting new log records and tries to // flush queues within the context timeout. Once complete all targets are shutdown // and any resources released. func (l *Logger) ShutdownAdvancedLogging(cxt context.Context) error { - err := l.logrLogger.Logr().ShutdownWithTimeout(cxt) - l.logrLogger = newLogr() + err := l.getLogger().Logr().ShutdownWithTimeout(cxt) + l.setLogger(newLogr()) return err } @@ -278,7 +281,7 @@ func (l *Logger) ConfigAdvancedLogging(targets LogTargetCfg) error { Error("error shutting down previous logger", Err(err)) } - err := logrAddTargets(l.logrLogger, targets) + err := logrAddTargets(l.getLogger(), targets) return err } @@ -286,7 +289,7 @@ func (l *Logger) ConfigAdvancedLogging(targets LogTargetCfg) error { // to add custom targets or provide configuration that cannot be expressed via a // config source. func (l *Logger) AddTarget(targets ...logr.Target) error { - return l.logrLogger.Logr().AddTarget(targets...) + return l.getLogger().Logr().AddTarget(targets...) } // RemoveTargets selectively removes targets that were previously added to this logger instance @@ -297,13 +300,27 @@ func (l *Logger) RemoveTargets(ctx context.Context, f func(ti TargetInfo) bool) fc := func(tic logr.TargetInfo) bool { return f(TargetInfo(tic)) } - return l.logrLogger.Logr().RemoveTargets(ctx, fc) + return l.getLogger().Logr().RemoveTargets(ctx, fc) } // EnableMetrics enables metrics collection by supplying a MetricsCollector. // The MetricsCollector provides counters and gauges that are updated by log targets. func (l *Logger) EnableMetrics(collector logr.MetricsCollector) error { - return l.logrLogger.Logr().SetMetricsCollector(collector) + return l.getLogger().Logr().SetMetricsCollector(collector) +} + +// getLogger is a concurrent safe getter of the logr logger +func (l *Logger) getLogger() *logr.Logger { + defer l.mutex.RUnlock() + l.mutex.RLock() + return l.logrLogger +} + +// setLogger is a concurrent safe setter of the logr logger +func (l *Logger) setLogger(logger *logr.Logger) { + defer l.mutex.Unlock() + l.mutex.Lock() + l.logrLogger = logger } // DisableZap is called to disable Zap, and Logr will be used instead. Any Logger diff --git a/mlog/log_test.go b/mlog/log_test.go new file mode 100644 index 0000000000..3616c8107f --- /dev/null +++ b/mlog/log_test.go @@ -0,0 +1,50 @@ +// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved. +// See LICENSE.txt for license information. + +package mlog_test + +import ( + "context" + "sync" + "testing" + + "github.com/mattermost/mattermost-server/v5/mlog" + "github.com/stretchr/testify/require" +) + +// Test race condition when shutting down advanced logging. This test must run with the -race flag in order to verify +// that there is no race. +func TestLogger_ShutdownAdvancedLoggingRace(t *testing.T) { + logger := mlog.NewLogger(&mlog.LoggerConfiguration{ + EnableConsole: true, + ConsoleJson: true, + EnableFile: false, + FileLevel: mlog.LevelInfo, + }) + started := make(chan bool) + ctx, cancel := context.WithCancel(context.Background()) + var wg sync.WaitGroup + + wg.Add(1) + go func() { + defer wg.Done() + started <- true + + for { + select { + case <-ctx.Done(): + return + default: + logger.Debug("testing...") + } + } + }() + + <-started + + err := logger.ShutdownAdvancedLogging(ctx) + require.NoError(t, err) + + cancel() + wg.Wait() +} diff --git a/mlog/testing.go b/mlog/testing.go index 1f2f437fac..c667283209 100644 --- a/mlog/testing.go +++ b/mlog/testing.go @@ -6,6 +6,7 @@ package mlog import ( "io" "strings" + "sync" "testing" "go.uber.org/zap" @@ -33,6 +34,7 @@ func NewTestingLogger(tb testing.TB, writer io.Writer) *Logger { consoleLevel: zap.NewAtomicLevelAt(getZapLevel("debug")), fileLevel: zap.NewAtomicLevelAt(getZapLevel("info")), logrLogger: newLogr(), + mutex: &sync.RWMutex{}, } logWriterCore := zapcore.NewCore(makeEncoder(true), zapcore.Lock(logWriterSync), testingLogger.consoleLevel)