fix mlog-ing before initialized (#8753)

Dump mlog to STDOUT before initialized, to allow for logging failures
that occur due to config parsing, etc.

Fix file logging to honour logger.FileJson instead of copying the
logger.ConsoleJson setting.

4 files changed, 210 insertions, 16 deletions

diff --git a/mlog/default.go b/mlog/default.go
new file mode 100644
index 000000000..366d22f88
--- /dev/null
+++ b/mlog/default.go
@@ -0,0 +1,50 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See License.txt for license information.
+
+package mlog
+
+import (
+	"encoding/json"
+	"fmt"
+)
+
+// defaultLog manually encodes the log to STDOUT, providing a basic, default logging implementation
+// before mlog is fully configured.
+func defaultLog(level, msg string, fields ...Field) {
+	log := struct {
+		Level   string  `json:"level"`
+		Message string  `json:"msg"`
+		Fields  []Field `json:"fields,omitempty"`
+	}{
+		level,
+		msg,
+		fields,
+	}
+
+	if b, err := json.Marshal(log); err != nil {
+		fmt.Printf(`{"level":"error","msg":"failed to encode log message"}%s`, "\n")
+	} else {
+		fmt.Printf("%s\n", b)
+	}
+}
+
+func defaultDebugLog(msg string, fields ...Field) {
+	defaultLog("debug", msg, fields...)
+}
+
+func defaultInfoLog(msg string, fields ...Field) {
+	defaultLog("info", msg, fields...)
+}
+
+func defaultWarnLog(msg string, fields ...Field) {
+	defaultLog("warn", msg, fields...)
+}
+
+func defaultErrorLog(msg string, fields ...Field) {
+	defaultLog("error", msg, fields...)
+}
+
+func defaultCriticalLog(msg string, fields ...Field) {
+	// We map critical to error in zap, so be consistent.
+	defaultLog("error", msg, fields...)
+}
diff --git a/mlog/global.go b/mlog/global.go
index 91d5858a4..36dd51afb 100644
--- a/mlog/global.go
+++ b/mlog/global.go
@@ -35,8 +35,8 @@ func GloballyEnableDebugLogForTest() {
 	globalLogger.consoleLevel.SetLevel(zapcore.DebugLevel)
 }
 
-var Debug LogFunc
-var Info LogFunc
-var Warn LogFunc
-var Error LogFunc
-var Critical LogFunc
+var Debug LogFunc = defaultDebugLog
+var Info LogFunc = defaultInfoLog
+var Warn LogFunc = defaultWarnLog
+var Error LogFunc = defaultErrorLog
+var Critical LogFunc = defaultCriticalLog
diff --git a/mlog/global_test.go b/mlog/global_test.go
new file mode 100644
index 000000000..c0ac022d0
--- /dev/null
+++ b/mlog/global_test.go
@@ -0,0 +1,143 @@
+package mlog_test
+
+import (
+	"io/ioutil"
+	"os"
+	"path/filepath"
+	"regexp"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/mattermost/mattermost-server/mlog"
+)
+
+func TestLoggingBeforeInitialized(t *testing.T) {
+	require.NotPanics(t, func() {
+		// None of these should segfault before mlog is globally configured
+		mlog.Info("info log")
+		mlog.Debug("debug log")
+		mlog.Warn("warning log")
+		mlog.Error("error log")
+		mlog.Critical("critical log")
+	})
+}
+
+func TestLoggingAfterInitialized(t *testing.T) {
+	testCases := []struct {
+		Description         string
+		LoggerConfiguration *mlog.LoggerConfiguration
+		ExpectedLogs        []string
+	}{
+		{
+			"file logging, json, debug",
+			&mlog.LoggerConfiguration{
+				EnableConsole: false,
+				EnableFile:    true,
+				FileJson:      true,
+				FileLevel:     mlog.LevelDebug,
+			},
+			[]string{
+				`{"level":"debug","ts":0,"caller":"mlog/global_test.go:0","msg":"real debug log"}`,
+				`{"level":"info","ts":0,"caller":"mlog/global_test.go:0","msg":"real info log"}`,
+				`{"level":"warn","ts":0,"caller":"mlog/global_test.go:0","msg":"real warning log"}`,
+				`{"level":"error","ts":0,"caller":"mlog/global_test.go:0","msg":"real error log"}`,
+				`{"level":"error","ts":0,"caller":"mlog/global_test.go:0","msg":"real critical log"}`,
+			},
+		},
+		{
+			"file logging, json, error",
+			&mlog.LoggerConfiguration{
+				EnableConsole: false,
+				EnableFile:    true,
+				FileJson:      true,
+				FileLevel:     mlog.LevelError,
+			},
+			[]string{
+				`{"level":"error","ts":0,"caller":"mlog/global_test.go:0","msg":"real error log"}`,
+				`{"level":"error","ts":0,"caller":"mlog/global_test.go:0","msg":"real critical log"}`,
+			},
+		},
+		{
+			"file logging, non-json, debug",
+			&mlog.LoggerConfiguration{
+				EnableConsole: false,
+				EnableFile:    true,
+				FileJson:      false,
+				FileLevel:     mlog.LevelDebug,
+			},
+			[]string{
+				`TIME	debug	mlog/global_test.go:0	real debug log`,
+				`TIME	info	mlog/global_test.go:0	real info log`,
+				`TIME	warn	mlog/global_test.go:0	real warning log`,
+				`TIME	error	mlog/global_test.go:0	real error log`,
+				`TIME	error	mlog/global_test.go:0	real critical log`,
+			},
+		},
+		{
+			"file logging, non-json, error",
+			&mlog.LoggerConfiguration{
+				EnableConsole: false,
+				EnableFile:    true,
+				FileJson:      false,
+				FileLevel:     mlog.LevelError,
+			},
+			[]string{
+				`TIME	error	mlog/global_test.go:0	real error log`,
+				`TIME	error	mlog/global_test.go:0	real critical log`,
+			},
+		},
+	}
+
+	for _, testCase := range testCases {
+		t.Run(testCase.Description, func(t *testing.T) {
+			var filePath string
+			if testCase.LoggerConfiguration.EnableFile {
+				tempDir, err := ioutil.TempDir(os.TempDir(), "TestLoggingAfterInitialized")
+				require.NoError(t, err)
+				defer os.Remove(tempDir)
+
+				filePath = filepath.Join(tempDir, "file.log")
+				testCase.LoggerConfiguration.FileLocation = filePath
+			}
+
+			logger := mlog.NewLogger(testCase.LoggerConfiguration)
+			mlog.InitGlobalLogger(logger)
+
+			mlog.Debug("real debug log")
+			mlog.Info("real info log")
+			mlog.Warn("real warning log")
+			mlog.Error("real error log")
+			mlog.Critical("real critical log")
+
+			if testCase.LoggerConfiguration.EnableFile {
+				logs, err := ioutil.ReadFile(filePath)
+				require.NoError(t, err)
+
+				actual := strings.TrimSpace(string(logs))
+
+				if testCase.LoggerConfiguration.FileJson {
+					reTs := regexp.MustCompile(`"ts":[0-9\.]+`)
+					reCaller := regexp.MustCompile(`"caller":"([^"]+):[0-9\.]+"`)
+					actual = reTs.ReplaceAllString(actual, `"ts":0`)
+					actual = reCaller.ReplaceAllString(actual, `"caller":"$1:0"`)
+				} else {
+					actualRows := strings.Split(actual, "\n")
+					for i, actualRow := range actualRows {
+						actualFields := strings.Split(actualRow, "\t")
+						if len(actualFields) > 3 {
+							actualFields[0] = "TIME"
+							reCaller := regexp.MustCompile(`([^"]+):[0-9\.]+`)
+							actualFields[2] = reCaller.ReplaceAllString(actualFields[2], "$1:0")
+							actualRows[i] = strings.Join(actualFields, "\t")
+						}
+					}
+
+					actual = strings.Join(actualRows, "\n")
+				}
+				require.Equal(t, testCase.ExpectedLogs, strings.Split(actual, "\n"))
+			}
+		})
+	}
+}
diff --git a/mlog/log.go b/mlog/log.go
index ad537a11d..0d1e28e8d 100644
--- a/mlog/log.go
+++ b/mlog/log.go
@@ -62,6 +62,16 @@ func getZapLevel(level string) zapcore.Level {
 	}
 }
 
+func makeEncoder(json bool) zapcore.Encoder {
+	encoderConfig := zap.NewProductionEncoderConfig()
+	if json {
+		return zapcore.NewJSONEncoder(encoderConfig)
+	}
+
+	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
+	return zapcore.NewConsoleEncoder(encoderConfig)
+}
+
 func NewLogger(config *LoggerConfiguration) *Logger {
 	cores := []zapcore.Core{}
 	logger := &Logger{
@@ -69,18 +79,9 @@ func NewLogger(config *LoggerConfiguration) *Logger {
 		fileLevel:    zap.NewAtomicLevelAt(getZapLevel(config.FileLevel)),
 	}
 
-	encoderConfig := zap.NewProductionEncoderConfig()
-	var encoder zapcore.Encoder
-	if config.ConsoleJson {
-		encoder = zapcore.NewJSONEncoder(encoderConfig)
-	} else {
-		encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
-		encoder = zapcore.NewConsoleEncoder(encoderConfig)
-	}
-
 	if config.EnableConsole {
 		writer := zapcore.Lock(os.Stdout)
-		core := zapcore.NewCore(encoder, writer, logger.consoleLevel)
+		core := zapcore.NewCore(makeEncoder(config.ConsoleJson), writer, logger.consoleLevel)
 		cores = append(cores, core)
 	}
 
@@ -90,7 +91,7 @@ func NewLogger(config *LoggerConfiguration) *Logger {
 			MaxSize:  100,
 			Compress: true,
 		})
-		core := zapcore.NewCore(encoder, writer, logger.fileLevel)
+		core := zapcore.NewCore(makeEncoder(config.FileJson), writer, logger.fileLevel)
 		cores = append(cores, core)
 	}