MM-27744 disable Zap for unit tests. (#15398)

MM-27744 disable Zap for unit tests. Zap has no concept of shutdown or close. Zap is only shutdown when the app exits. Not a problem for console logging, but when creating a new Zap logger that outputs to files on every unit test, that leaves no easy way to clean up until process exit. Depending on what else is running this can exhaust all file handles and cause unit tests to fail. Zap is now disabled unit tests and uses Logr instead, regardless of config settings. `make test-server` peak file handle usage dropped from ~5K to less than 100.
2020-09-09 15:25:55 -04:00
--- a/mlog/default.go
+++ b/mlog/default.go
@@ -76,12 +76,18 @@ func defaultAdvancedShutdown(ctx context.Context) error {
 	return nil
 }

-func defaultAddTarget(target logr.Target) error {
+func defaultAddTarget(targets ...logr.Target) error {
 	// mlog.AddTarget should not be called until default
 	// logger is replaced with mlog.Logger instance.
 	return errors.New("cannot AddTarget on default logger")
 }

+func defaultRemoveTargets(ctx context.Context, f func(TargetInfo) bool) error {
+	// mlog.RemoveTargets should not be called until default
+	// logger is replaced with mlog.Logger instance.
+	return errors.New("cannot RemoveTargets on default logger")
+}
+
 func defaultEnableMetrics(collector logr.MetricsCollector) error {
 	// mlog.EnableMetrics should not be called until default
 	// logger is replaced with mlog.Logger instance.
--- a/mlog/global.go
+++ b/mlog/global.go
@@ -5,6 +5,8 @@ package mlog

 import (
 	"context"
+	"log"
+	"sync/atomic"

 	"github.com/mattermost/logr"
 	"go.uber.org/zap"
@@ -32,11 +34,29 @@ func InitGlobalLogger(logger *Logger) {
 	ConfigAdvancedLogging = globalLogger.ConfigAdvancedLogging
 	ShutdownAdvancedLogging = globalLogger.ShutdownAdvancedLogging
 	AddTarget = globalLogger.AddTarget
+	RemoveTargets = globalLogger.RemoveTargets
 	EnableMetrics = globalLogger.EnableMetrics
 }

+// logWriterFunc provides access to mlog via io.Writer, so the standard logger
+// can be redirected to use mlog and whatever targets are defined.
+type logWriterFunc func([]byte) (int, error)
+
+func (lw logWriterFunc) Write(p []byte) (int, error) {
+	return lw(p)
+}
+
 func RedirectStdLog(logger *Logger) {
-	zap.RedirectStdLogAt(logger.zap.With(zap.String("source", "stdlog")).WithOptions(zap.AddCallerSkip(-2)), zapcore.ErrorLevel)
+	if atomic.LoadInt32(&disableZap) == 0 {
+		zap.RedirectStdLogAt(logger.zap.With(zap.String("source", "stdlog")).WithOptions(zap.AddCallerSkip(-2)), zapcore.ErrorLevel)
+		return
+	}
+
+	writer := func(p []byte) (int, error) {
+		Log(LvlStdLog, string(p))
+		return len(p), nil
+	}
+	log.SetOutput(logWriterFunc(writer))
 }

 type LogFunc func(string, ...Field)
@@ -45,7 +65,8 @@ type LogFuncCustomMulti func([]LogLevel, string, ...Field)
 type FlushFunc func(context.Context) error
 type ConfigFunc func(cfg LogTargetCfg) error
 type ShutdownFunc func(context.Context) error
-type AddTargetFunc func(logr.Target) error
+type AddTargetFunc func(...logr.Target) error
+type RemoveTargetsFunc func(context.Context, func(TargetInfo) bool) error
 type EnableMetricsFunc func(logr.MetricsCollector) error

 // DON'T USE THIS Modify the level on the app logger
@@ -70,4 +91,5 @@ var Flush FlushFunc = defaultFlush
 var ConfigAdvancedLogging ConfigFunc = defaultAdvancedConfig
 var ShutdownAdvancedLogging ShutdownFunc = defaultAdvancedShutdown
 var AddTarget AddTargetFunc = defaultAddTarget
+var RemoveTargets RemoveTargetsFunc = defaultRemoveTargets
 var EnableMetrics EnableMetricsFunc = defaultEnableMetrics
--- a/mlog/levels.go
+++ b/mlog/levels.go
@@ -5,13 +5,15 @@ package mlog

 // Standard levels
 var (
-	LvlPanic = LogLevel{ID: 0, Name: "panic"}
-	LvlFatal = LogLevel{ID: 1, Name: "fatal"}
+	LvlPanic = LogLevel{ID: 0, Name: "panic", Stacktrace: true}
+	LvlFatal = LogLevel{ID: 1, Name: "fatal", Stacktrace: true}
 	LvlError = LogLevel{ID: 2, Name: "error"}
 	LvlWarn  = LogLevel{ID: 3, Name: "warn"}
 	LvlInfo  = LogLevel{ID: 4, Name: "info"}
 	LvlDebug = LogLevel{ID: 5, Name: "debug"}
 	LvlTrace = LogLevel{ID: 6, Name: "trace"}
+	// used by redirected standard logger
+	LvlStdLog = LogLevel{ID: 10, Name: "stdlog"}
 	// used only by the logger
 	LvlLogError = LogLevel{ID: 11, Name: "logerror", Stacktrace: true}
 )
--- a/mlog/log.go
+++ b/mlog/log.go
@@ -5,9 +5,12 @@ package mlog

 import (
 	"context"
+	"fmt"
 	"io"
 	"log"
 	"os"
+	"sync/atomic"
+	"time"

 	"github.com/mattermost/logr"
 	"go.uber.org/zap"
@@ -24,6 +27,19 @@ const (
 	LevelWarn = "warn"
 	// Errors are messages about things we know are problems
 	LevelError = "error"
+
+	// DefaultFlushTimeout is the default amount of time mlog.Flush will wait
+	// before timing out.
+	DefaultFlushTimeout = time.Second * 5
+)
+
+var (
+	// disableZap is set when Zap should be disabled and Logr used instead.
+	// This is needed for unit testing as Zap has no shutdown capabilities
+	// and holds file handles until process exit. Currently unit test create
+	// many server instances, and thus many Zap log files.
+	// This flag will be removed when Zap is permanently replaced.
+	disableZap int32
 )

 // Type and function aliases from zap to limit the libraries scope into MM code
@@ -40,6 +56,8 @@ var NamedErr = zap.NamedError
 var Bool = zap.Bool
 var Duration = zap.Duration

+type TargetInfo logr.TargetInfo
+
 type LoggerConfiguration struct {
 	EnableConsole bool
 	ConsoleJson   bool
@@ -97,14 +115,33 @@ func NewLogger(config *LoggerConfiguration) *Logger {
 	}

 	if config.EnableFile {
-		writer := zapcore.AddSync(&lumberjack.Logger{
-			Filename: config.FileLocation,
-			MaxSize:  100,
-			Compress: true,
-		})
+		if atomic.LoadInt32(&disableZap) != 0 {
+			t := &LogTarget{
+				Type:         "file",
+				Format:       "json",
+				Levels:       mlogLevelToLogrLevels(config.FileLevel),
+				MaxQueueSize: DefaultMaxTargetQueue,
+				Options: []byte(fmt.Sprintf(`{"Filename":"%s", "MaxSizeMB":%d, "Compress":%t}`,
+					config.FileLocation, 100, true)),
+			}
+			if !config.FileJson {
+				t.Format = "plain"
+			}
+			if tgt, err := NewLogrTarget("mlogFile", t); err == nil {
+				logger.logrLogger.Logr().AddTarget(tgt)
+			} else {
+				Error("error creating mlogFile", Err(err))
+			}
+		} else {
+			writer := zapcore.AddSync(&lumberjack.Logger{
+				Filename: config.FileLocation,
+				MaxSize:  100,
+				Compress: true,
+			})

-		core := zapcore.NewCore(makeEncoder(config.FileJson), writer, logger.fileLevel)
-		cores = append(cores, core)
+			core := zapcore.NewCore(makeEncoder(config.FileJson), writer, logger.fileLevel)
+			cores = append(cores, core)
+		}
 	}

 	combinedCore := zapcore.NewTee(cores...)
@@ -221,14 +258,14 @@ func (l *Logger) LogM(levels []LogLevel, message string, fields ...Field) {
 }

 func (l *Logger) Flush(cxt context.Context) error {
-	return l.logrLogger.Logr().Flush() // TODO: use context when Logr lib supports it.
+	return l.logrLogger.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().Shutdown() // TODO: use context when Logr lib supports it.
+	err := l.logrLogger.Logr().ShutdownWithTimeout(cxt)
 	l.logrLogger = newLogr()
 	return err
 }
@@ -245,11 +282,22 @@ func (l *Logger) ConfigAdvancedLogging(targets LogTargetCfg) error {
 	return err
 }

-// AddTarget adds a logr.Target to the advanced logger. This is the preferred method
+// AddTarget adds one or more logr.Target to the advanced logger. This is the preferred method
 // to add custom targets or provide configuration that cannot be expressed via a
-//config source.
-func (l *Logger) AddTarget(target logr.Target) error {
-	return l.logrLogger.Logr().AddTarget(target)
+// config source.
+func (l *Logger) AddTarget(targets ...logr.Target) error {
+	return l.logrLogger.Logr().AddTarget(targets...)
+}
+
+// RemoveTargets selectively removes targets that were previously added to this logger instance
+// using the passed in filter function. The filter function should return true to remove the target
+// and false to keep it.
+func (l *Logger) RemoveTargets(ctx context.Context, f func(ti TargetInfo) bool) error {
+	// Use locally defined TargetInfo type so we don't spread Logr dependencies.
+	fc := func(tic logr.TargetInfo) bool {
+		return f(TargetInfo(tic))
+	}
+	return l.logrLogger.Logr().RemoveTargets(ctx, fc)
 }

 // EnableMetrics enables metrics collection by supplying a MetricsCollector.
@@ -257,3 +305,21 @@ func (l *Logger) AddTarget(target logr.Target) error {
 func (l *Logger) EnableMetrics(collector logr.MetricsCollector) error {
 	return l.logrLogger.Logr().SetMetricsCollector(collector)
 }
+
+// DisableZap is called to disable Zap, and Logr will be used instead. Any Logger
+// instances created after this call will only use Logr.
+//
+// This is needed for unit testing as Zap has no shutdown capabilities
+// and holds file handles until process exit. Currently unit tests create
+// many server instances, and thus many Zap log file handles.
+//
+// This method will be removed when Zap is permanently replaced.
+func DisableZap() {
+	atomic.StoreInt32(&disableZap, 1)
+}
+
+// EnableZap re-enables Zap such that any Logger instances created after this
+// call will allow Zap targets.
+func EnableZap() {
+	atomic.StoreInt32(&disableZap, 0)
+}
--- a/mlog/logr.go
+++ b/mlog/logr.go
@@ -60,6 +60,7 @@ func logrAddTargets(logger *logr.Logger, targets LogTargetCfg) error {
 			continue
 		}
 		if target != nil {
+			target.SetName(name)
 			lgr.AddTarget(target)
 		}
 	}
@@ -152,15 +153,18 @@ func newFileTarget(name string, t *LogTarget, filter logr.Filter, formatter logr
 	if err := json.Unmarshal(t.Options, options); err != nil {
 		return nil, err
 	}
+	return newFileTargetWithOpts(name, t, target.FileOptions(*options), filter, formatter)
+}

-	if options.Filename == "" {
+func newFileTargetWithOpts(name string, t *LogTarget, opts target.FileOptions, filter logr.Filter, formatter logr.Formatter) (logr.Target, error) {
+	if opts.Filename == "" {
 		return nil, fmt.Errorf("missing 'Filename' option for target %s", name)
 	}
-	if err := checkFileWritable(options.Filename); err != nil {
+	if err := checkFileWritable(opts.Filename); err != nil {
 		return nil, fmt.Errorf("error writing to 'Filename' for target %s: %w", name, err)
 	}

-	newTarget := target.NewFileTarget(filter, formatter, target.FileOptions(*options), t.MaxQueueSize)
+	newTarget := target.NewFileTarget(filter, formatter, opts, t.MaxQueueSize)
 	return newTarget, nil
 }

@@ -222,3 +226,22 @@ func zapToLogr(zapFields []Field) logr.Fields {
 	}
 	return logr.Fields(encoder.Fields)
 }
+
+// mlogLevelToLogrLevel converts a mlog logger level to
+// an array of discrete Logr levels.
+func mlogLevelToLogrLevels(level string) []LogLevel {
+	levels := make([]LogLevel, 0)
+	levels = append(levels, LvlError, LvlPanic, LvlFatal, LvlStdLog)
+
+	switch level {
+	case LevelDebug:
+		levels = append(levels, LvlDebug)
+		fallthrough
+	case LevelInfo:
+		levels = append(levels, LvlInfo)
+		fallthrough
+	case LevelWarn:
+		levels = append(levels, LvlWarn)
+	}
+	return levels
+}