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.

api4/main_test.go

@@ -6,6 +6,7 @@ package api4
 import (
 	"testing"
 
+	"github.com/mattermost/mattermost-server/v5/mlog"
 	"github.com/mattermost/mattermost-server/v5/testlib"
 )
 
@@ -15,6 +16,8 @@ func TestMain(m *testing.M) {
 		EnableResources: true,
 	}
 
+	mlog.DisableZap()
+
 	mainHelper = testlib.NewMainHelperWithOptions(&options)
 	defer mainHelper.Close()
 

app/admin.go

@@ -4,6 +4,7 @@
 package app
 
 import (
+	"context"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -59,6 +60,10 @@ func (s *Server) GetLogsSkipSend(page, perPage int) ([]string, *model.AppError)
 	var lines []string
 
 	if *s.Config().LogSettings.EnableFile {
+		timeoutCtx, timeoutCancel := context.WithTimeout(context.Background(), mlog.DefaultFlushTimeout)
+		defer timeoutCancel()
+		mlog.Flush(timeoutCtx)
+
 		logFile := utils.GetLogFileLocation(*s.Config().LogSettings.FileLocation)
 		file, err := os.Open(logFile)
 		if err != nil {

app/main_test.go

@@ -6,6 +6,7 @@ package app
 import (
 	"testing"
 
+	"github.com/mattermost/mattermost-server/v5/mlog"
 	"github.com/mattermost/mattermost-server/v5/testlib"
 )
 
@@ -17,6 +18,8 @@ func TestMain(m *testing.M) {
 		EnableResources: true,
 	}
 
+	mlog.DisableZap()
+
 	mainHelper = testlib.NewMainHelperWithOptions(&options)
 	defer mainHelper.Close()
 

app/server.go

@@ -115,20 +115,20 @@ type Server struct {
 
 	newStore func() store.Store
 
-	htmlTemplateWatcher            *utils.HTMLTemplateWatcher
-	sessionCache                   cache.Cache
-	seenPendingPostIdsCache        cache.Cache
-	statusCache                    cache.Cache
-	configListenerId               string
-	licenseListenerId              string
-	logListenerId                  string
-	clusterLeaderListenerId        string
-	searchConfigListenerId         string
-	searchLicenseListenerId        string
-	loggerMetricsLicenseListenerId string
-	configStore                    config.Store
-	asymmetricSigningKey           *ecdsa.PrivateKey
-	postActionCookieSecret         []byte
+	htmlTemplateWatcher     *utils.HTMLTemplateWatcher
+	sessionCache            cache.Cache
+	seenPendingPostIdsCache cache.Cache
+	statusCache             cache.Cache
+	configListenerId        string
+	licenseListenerId       string
+	logListenerId           string
+	clusterLeaderListenerId string
+	searchConfigListenerId  string
+	searchLicenseListenerId string
+	loggerLicenseListenerId string
+	configStore             config.Store
+	asymmetricSigningKey    *ecdsa.PrivateKey
+	postActionCookieSecret  []byte
 
 	advancedLogListenerCleanup func()
 
@@ -480,19 +480,11 @@ func NewServer(options ...Option) (*Server, error) {
 		}
 	}
 
-	if !allowAdvancedLogging {
-		timeoutCtx, cancelCtx := context.WithTimeout(context.Background(), time.Second*5)
-		defer cancelCtx()
-		mlog.Info("Shutting down advanced logging")
-		mlog.ShutdownAdvancedLogging(timeoutCtx)
-		if s.advancedLogListenerCleanup != nil {
-			s.advancedLogListenerCleanup()
-			s.advancedLogListenerCleanup = nil
-		}
-	}
-
+	s.removeUnlicensedLogTargets(license)
 	s.enableLoggingMetrics()
-	s.loggerMetricsLicenseListenerId = s.AddLicenseListener(func(oldLicense, newLicense *model.License) {
+
+	s.loggerLicenseListenerId = s.AddLicenseListener(func(oldLicense, newLicense *model.License) {
+		s.removeUnlicensedLogTargets(newLicense)
 		s.enableLoggingMetrics()
 	})
 
@@ -561,6 +553,7 @@ func (s *Server) AppOptions() []AppOption {
 	}
 }
 
+// initLogging initializes and configures the logger. This may be called more than once.
 func (s *Server) initLogging() error {
 	if s.Log == nil {
 		s.Log = mlog.NewLogger(utils.MloggerConfigFromLoggerConfig(&s.Config().LogSettings, utils.GetLogFileLocation))
@@ -578,6 +571,9 @@ func (s *Server) initLogging() error {
 	// Use this app logger as the global logger (eventually remove all instances of global logging)
 	mlog.InitGlobalLogger(s.Log)
 
+	if s.logListenerId != "" {
+		s.RemoveConfigListener(s.logListenerId)
+	}
 	s.logListenerId = s.AddConfigListener(func(_, after *model.Config) {
 		s.Log.ChangeLevels(utils.MloggerConfigFromLoggerConfig(&after.LogSettings, utils.GetLogFileLocation))
 
@@ -633,13 +629,27 @@ func (s *Server) initLogging() error {
 	return nil
 }
 
+func (s *Server) removeUnlicensedLogTargets(license *model.License) {
+	if license != nil && *license.Features.AdvancedLogging {
+		// advanced logging enabled via license; no need to remove any targets
+		return
+	}
+
+	timeoutCtx, cancelCtx := context.WithTimeout(context.Background(), time.Second*10)
+	defer cancelCtx()
+
+	mlog.RemoveTargets(timeoutCtx, func(ti mlog.TargetInfo) bool {
+		return ti.Type != "*target.Writer" && ti.Type != "*target.File"
+	})
+}
+
 func (s *Server) enableLoggingMetrics() {
 	if s.Metrics == nil {
 		return
 	}
 
 	if err := mlog.EnableMetrics(s.Metrics.GetLoggerMetricsCollector()); err != nil {
-		mlog.Debug("Failed to enable advanced logging metrics", mlog.Err(err))
+		mlog.Error("Failed to enable advanced logging metrics", mlog.Err(err))
 	} else {
 		mlog.Debug("Advanced logging metrics enabled")
 	}
@@ -677,7 +687,7 @@ func (s *Server) Shutdown() error {
 	s.HubStop()
 	s.ShutDownPlugins()
 	s.RemoveLicenseListener(s.licenseListenerId)
-	s.RemoveLicenseListener(s.loggerMetricsLicenseListenerId)
+	s.RemoveLicenseListener(s.loggerLicenseListenerId)
 	s.RemoveClusterLeaderChangedListener(s.clusterLeaderListenerId)
 
 	if s.tracer != nil {

app/server_test.go

@@ -304,6 +304,10 @@ func TestPanicLog(t *testing.T) {
 		require.NoError(t, os.Remove(tmpfile.Name()))
 	}()
 
+	// This test requires Zap file target for now.
+	mlog.EnableZap()
+	defer mlog.DisableZap()
+
 	// Creating logger to log to console and temp file
 	logger := mlog.NewLogger(&mlog.LoggerConfiguration{
 		EnableConsole: true,

app/slashcommands/main_test.go

@@ -6,6 +6,7 @@ package slashcommands
 import (
 	"testing"
 
+	"github.com/mattermost/mattermost-server/v5/mlog"
 	"github.com/mattermost/mattermost-server/v5/testlib"
 )
 
@@ -17,6 +18,8 @@ func TestMain(m *testing.M) {
 		EnableResources: true,
 	}
 
+	mlog.DisableZap()
+
 	mainHelper = testlib.NewMainHelperWithOptions(&options)
 	defer mainHelper.Close()
 

cmd/mattermost/commands/main_test.go

@@ -9,6 +9,7 @@ import (
 	"testing"
 
 	"github.com/mattermost/mattermost-server/v5/api4"
+	"github.com/mattermost/mattermost-server/v5/mlog"
 	"github.com/mattermost/mattermost-server/v5/testlib"
 )
 
@@ -27,6 +28,8 @@ func TestMain(m *testing.M) {
 		EnableResources: true,
 	}
 
+	mlog.DisableZap()
+
 	mainHelper = testlib.NewMainHelperWithOptions(&options)
 	defer mainHelper.Close()
 	api4.SetMainHelper(mainHelper)

config/main_test.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/go-sql-driver/mysql"
 	"github.com/lib/pq"
+	"github.com/mattermost/mattermost-server/v5/mlog"
 	"github.com/mattermost/mattermost-server/v5/model"
 	"github.com/mattermost/mattermost-server/v5/testlib"
 	"github.com/stretchr/testify/require"
@@ -21,6 +22,8 @@ func TestMain(m *testing.M) {
 		EnableStore: true,
 	}
 
+	mlog.DisableZap()
+
 	mainHelper = testlib.NewMainHelperWithOptions(&options)
 	defer mainHelper.Close()
 

go.mod

@@ -60,7 +60,7 @@ require (
 	github.com/mattermost/gorp v1.6.2-0.20200624165429-2595d5e54111
 	github.com/mattermost/gosaml2 v0.3.2
 	github.com/mattermost/ldap v0.0.0-20191128190019-9f62ba4b8d4d
-	github.com/mattermost/logr v1.0.9
+	github.com/mattermost/logr v1.0.13
 	github.com/mattermost/rsc v0.0.0-20160330161541-bbaefb05eaa0
 	github.com/mattermost/viper v1.0.4
 	github.com/mattn/go-colorable v0.1.7 // indirect

go.sum

@@ -484,6 +484,14 @@ github.com/mattermost/ldap v0.0.0-20191128190019-9f62ba4b8d4d h1:2DV7VIlEv6J5R5o
 github.com/mattermost/ldap v0.0.0-20191128190019-9f62ba4b8d4d/go.mod h1:HLbgMEI5K131jpxGazJ97AxfPDt31osq36YS1oxFQPQ=
 github.com/mattermost/logr v1.0.9 h1:jw6f6CjPC2YfPqzpGVM/vCGuqKLJdVS400ZRTFtEQwQ=
 github.com/mattermost/logr v1.0.9/go.mod h1:Mt4DPu1NXMe6JxPdwCC0XBoxXmN9eXOIRPoZarU2PXs=
+github.com/mattermost/logr v1.0.10 h1:J/M6OFJhzQCUPGLyL9s8hiE+8nyL7Y0DybbOxYOisi0=
+github.com/mattermost/logr v1.0.10/go.mod h1:Mt4DPu1NXMe6JxPdwCC0XBoxXmN9eXOIRPoZarU2PXs=
+github.com/mattermost/logr v1.0.11 h1:XlNLB3x9OhvoNxEus46dW38zejINe5D2dZBlwmIlX5Q=
+github.com/mattermost/logr v1.0.11/go.mod h1:Mt4DPu1NXMe6JxPdwCC0XBoxXmN9eXOIRPoZarU2PXs=
+github.com/mattermost/logr v1.0.12 h1:1Tt2dJppjW6XlpJgMpeN+SNG1QgbTr4ITYnxG3NLPbM=
+github.com/mattermost/logr v1.0.12/go.mod h1:Mt4DPu1NXMe6JxPdwCC0XBoxXmN9eXOIRPoZarU2PXs=
+github.com/mattermost/logr v1.0.13 h1:6F/fM3csvH6Oy5sUpJuW7YyZSzZZAhJm5VcgKMxA2P8=
+github.com/mattermost/logr v1.0.13/go.mod h1:Mt4DPu1NXMe6JxPdwCC0XBoxXmN9eXOIRPoZarU2PXs=
 github.com/mattermost/rsc v0.0.0-20160330161541-bbaefb05eaa0 h1:G9tL6JXRBMzjuD1kkBtcnd42kUiT6QDwxfFYu7adM6o=
 github.com/mattermost/rsc v0.0.0-20160330161541-bbaefb05eaa0/go.mod h1:nV5bfVpT//+B1RPD2JvRnxbkLmJEYXmRaaVl15fsXjs=
 github.com/mattermost/viper v1.0.4 h1:cMYOz4PhguscGSPxrSokUtib5HrG4gCpiUh27wyA3d0=

migrations/main_test.go

@@ -6,6 +6,7 @@ package migrations
 import (
 	"testing"
 
+	"github.com/mattermost/mattermost-server/v5/mlog"
 	"github.com/mattermost/mattermost-server/v5/testlib"
 )
 
@@ -17,6 +18,8 @@ func TestMain(m *testing.M) {
 		EnableResources: true,
 	}
 
+	mlog.DisableZap()
+
 	mainHelper = testlib.NewMainHelperWithOptions(&options)
 	defer mainHelper.Close()
 

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.

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

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}
 )