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.

1 files changed, 143 insertions, 0 deletions

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