Make mlogger atomic (#16398)

* Make mlogger atomic * Apply PR suggestions * Fix logger initialization on testing * Apply PR suggestions
2020-11-25 12:30:42 +02:00
--- 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
--- a/mlog/log_test.go
+++ 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()
+}
--- 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)