From b4db76cedbd99bfcfb1c12444c5bd84e92ac01dc Mon Sep 17 00:00:00 2001 From: Jesse Hallam Date: Fri, 11 May 2018 12:56:54 -0400 Subject: 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. --- mlog/default.go | 50 ++++++++++++++++++ mlog/global.go | 10 ++-- mlog/global_test.go | 143 ++++++++++++++++++++++++++++++++++++++++++++++++++++ mlog/log.go | 23 +++++---- 4 files changed, 210 insertions(+), 16 deletions(-) create mode 100644 mlog/default.go create mode 100644 mlog/global_test.go (limited to 'mlog') 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) } -- cgit v1.2.3-1-g7c22