Commit b4db76ce authored by Jesse Hallam's avatar Jesse Hallam Committed by Derrick Anderson

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.
parent 91c99815
// 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...)
}
......@@ -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
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"))
}
})
}
}
......@@ -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)
}
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment