From 74b5e52c4eb54000dcb5a7b46c0977d732bce80f Mon Sep 17 00:00:00 2001 From: Jonathan Date: Thu, 31 Aug 2017 15:59:03 -0400 Subject: PLT-3893: Structured Logging Continues (#7252) * PLT-3893: Imported logger work from https://github.com/MusikPolice/platform * PLT-3893: Integrated logger with system config * PLT-3893: Integrated Mattermost config with logging solution, modified log message serialization so entire message is serialized as a JSON object * PLT-3893: Added support for format strings in Debug methods. Added an overload that does not require a Context object for cases when one isn't available * PLT-3893: Added context and format string support to debug and error methods * PLT-3893: A few updates from pull request feedback * PLT-3893: Changed tests to use testify * Fixed TestAddRemoveConfigListener to no longer assume that there are zero config listeners when the test begins, since other tests could add config listeners * Updated TestGetDeletedChannelsForTeam so that it doesn't assume state when it begins * PLT-3893: Changed File property of log message so that it's relative to /mattermost directory, rather than to wherever the user is running the application from on their machine * Flipped expected/actual assert arguments, added an explicit test for getCallerFilename(...), since it's failing on Jenkins * Added printlns to debug failing tests on Jenkins * Relaxed test cases to avoid failure on Jenkins caused by code coverage calculations. Removed printlns. * Changed the way that caller filename is determined to make it more robust, updated tests to make them more lax, while not choking on the strange paths that Jenkins uses. * Fixed gofmt issues * Added debug output to tests to diagnose Jenkins build failures * Still trying to get some useful debug logging on Jenkins * Changed getCallerFilename to handle the strange paths that runtime.Caller(...) returns on Jenkins * Fixing checkstyle issues --- utils/logger/log4go_json_writer.go | 27 ++++ utils/logger/logger.go | 224 +++++++++++++++++++++++++++++ utils/logger/logger_test.go | 287 +++++++++++++++++++++++++++++++++++++ 3 files changed, 538 insertions(+) create mode 100644 utils/logger/log4go_json_writer.go create mode 100644 utils/logger/logger.go create mode 100644 utils/logger/logger_test.go (limited to 'utils/logger') diff --git a/utils/logger/log4go_json_writer.go b/utils/logger/log4go_json_writer.go new file mode 100644 index 000000000..97a8af76b --- /dev/null +++ b/utils/logger/log4go_json_writer.go @@ -0,0 +1,27 @@ +// glue functions that allow logger.go to leverage log4Go to write JSON-formatted log records to a file + +package logger + +import ( + l4g "github.com/alecthomas/log4go" + "github.com/mattermost/platform/utils" +) + +// newJSONLogWriter is a utility method for creating a FileLogWriter set up to +// output JSON record log messages instead of line-based ones. +func newJSONLogWriter(fname string, rotate bool) *l4g.FileLogWriter { + return l4g.NewFileLogWriter(fname, rotate).SetFormat( + `{"level": "%L", + "timestamp": "%D %T", + "source": "%S", + "message": %M + }`).SetRotateLines(utils.LOG_ROTATE_SIZE) +} + +// NewJSONFileLogger - Create a new logger with a "file" filter configured to send JSON-formatted log messages at +// or above lvl to a file with the specified filename. +func NewJSONFileLogger(lvl l4g.Level, filename string) l4g.Logger { + return l4g.Logger{ + "file": &l4g.Filter{Level: lvl, LogWriter: newJSONLogWriter(filename, true)}, + } +} diff --git a/utils/logger/logger.go b/utils/logger/logger.go new file mode 100644 index 000000000..dc4aec19f --- /dev/null +++ b/utils/logger/logger.go @@ -0,0 +1,224 @@ +// this is a new logger interface for mattermost + +package logger + +import ( + "context" + "encoding/json" + "fmt" + "path/filepath" + "runtime" + + l4g "github.com/alecthomas/log4go" + + "github.com/mattermost/platform/model" + "github.com/mattermost/platform/utils" + "github.com/pkg/errors" + "strings" +) + +// this pattern allows us to "mock" the underlying l4g code when unit testing +var debugLog = l4g.Debug +var infoLog = l4g.Info +var errorLog = l4g.Error + +func init() { + initL4g(utils.Cfg.LogSettings) +} + +// listens for configuration changes that we might need to respond to +var configListenerID = utils.AddConfigListener(func(oldConfig *model.Config, newConfig *model.Config) { + infoLog("Configuration change detected, reloading log settings") + initL4g(newConfig.LogSettings) +}) + +// assumes that ../config.go::configureLog has already been called, and has in turn called l4g.close() to clean up +// any old filters that we might have previously created +func initL4g(logSettings model.LogSettings) { + // TODO: add support for newConfig.LogSettings.EnableConsole. Right now, ../config.go sets it up in its configureLog + // method. If we also set it up here, messages will be written to the console twice. Eventually, when all instances + // of l4g have been replaced by this logger, we can move that code to here + if logSettings.EnableFile { + level := l4g.DEBUG + if logSettings.FileLevel == "INFO" { + level = l4g.INFO + } else if logSettings.FileLevel == "WARN" { + level = l4g.WARNING + } else if logSettings.FileLevel == "ERROR" { + level = l4g.ERROR + } + + // create a logger that writes JSON objects to a file, and override our log methods to use it + flw := NewJSONFileLogger(level, utils.GetLogFileLocation(logSettings.FileLocation)+".jsonl") + debugLog = flw.Debug + infoLog = flw.Info + errorLog = flw.Error + } +} + +// contextKey lets us add contextual information to log messages +type contextKey string + +func (c contextKey) String() string { + return string(c) +} + +const contextKeyUserID contextKey = contextKey("user_id") +const contextKeyRequestID contextKey = contextKey("request_id") + +// any contextKeys added to this array will be serialized in every log message +var contextKeys = [2]contextKey{contextKeyUserID, contextKeyRequestID} + +// WithUserId adds a user id to the specified context. If the returned Context is subsequently passed to a logging +// method, the user id will automatically be included in the logged message +func WithUserId(ctx context.Context, userID string) context.Context { + return context.WithValue(ctx, contextKeyUserID, userID) +} + +// WithRequestId adds a request id to the specified context. If the returned Context is subsequently passed to a logging +// method, the request id will automatically be included in the logged message +func WithRequestId(ctx context.Context, requestID string) context.Context { + return context.WithValue(ctx, contextKeyRequestID, requestID) +} + +// extracts known contextKey values from the specified Context and assembles them into the returned map +func serializeContext(ctx context.Context) map[string]string { + serialized := make(map[string]string) + for _, key := range contextKeys { + value, ok := ctx.Value(key).(string) + if ok { + serialized[string(key)] = value + } + } + return serialized +} + +// Returns the path to the next file up the callstack that has a different name than this file +// in other words, finds the path to the file that is doing the logging. +// Removes machine-specific prefix, so returned path starts with /platform. +// Looks a maximum of 10 frames up the call stack to find a file that has a different name than this one. +func getCallerFilename() (string, error) { + _, currentFilename, _, ok := runtime.Caller(0) + if !ok { + return "", errors.New("Failed to traverse stack frame") + } + + platformDirectory := currentFilename + for filepath.Base(platformDirectory) != "platform" { + platformDirectory = filepath.Dir(platformDirectory) + if platformDirectory == "." || platformDirectory == string(filepath.Separator) { + break + } + } + + for i := 1; i < 10; i++ { + _, parentFilename, _, ok := runtime.Caller(i) + if !ok { + return "", errors.New("Failed to traverse stack frame") + } else if parentFilename != currentFilename && strings.Contains(parentFilename, platformDirectory) { + // trim parentFilename such that we return the path to parentFilename, relative to platformDirectory + return parentFilename[strings.LastIndex(parentFilename, platformDirectory)+len(platformDirectory)+1:], nil + } + } + return "", errors.New("Failed to traverse stack frame") +} + +// creates a JSON representation of a log message +func serializeLogMessage(ctx context.Context, message string) string { + callerFilename, err := getCallerFilename() + if err != nil { + callerFilename = "Unknown" + } + + bytes, err := json.Marshal(&struct { + Context map[string]string `json:"context"` + File string `json:"file"` + Message string `json:"message"` + }{ + serializeContext(ctx), + callerFilename, + message, + }) + if err != nil { + errorLog("Failed to serialize log message %v", message) + } + return string(bytes) +} + +func formatMessage(args ...interface{}) string { + msg, ok := args[0].(string) + if !ok { + panic("Second argument is not of type string") + } + if len(args) > 1 { + variables := args[1:] + msg = fmt.Sprintf(msg, variables...) + } + return msg +} + +// Debugc logs a debugLog level message, including context information that is stored in the first parameter. +// If two parameters are supplied, the second must be a message string, and will be logged directly. +// If more than two parameters are supplied, the second parameter must be a format string, and the remaining parameters +// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function. +func Debugc(ctx context.Context, args ...interface{}) { + debugLog(func() string { + msg := formatMessage(args...) + return serializeLogMessage(ctx, msg) + }) +} + +// Debugf logs a debugLog level message. +// If one parameter is supplied, it must be a message string, and will be logged directly. +// If two or more parameters are specified, the first parameter must be a format string, and the remaining parameters +// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function. +func Debugf(args ...interface{}) { + debugLog(func() string { + msg := formatMessage(args...) + return serializeLogMessage(context.Background(), msg) + }) +} + +// Infoc logs an infoLog level message, including context information that is stored in the first parameter. +// If two parameters are supplied, the second must be a message string, and will be logged directly. +// If more than two parameters are supplied, the second parameter must be a format string, and the remaining parameters +// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function. +func Infoc(ctx context.Context, args ...interface{}) { + infoLog(func() string { + msg := formatMessage(args...) + return serializeLogMessage(ctx, msg) + }) +} + +// Infof logs an infoLog level message. +// If one parameter is supplied, it must be a message string, and will be logged directly. +// If two or more parameters are specified, the first parameter must be a format string, and the remaining parameters +// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function. +func Infof(args ...interface{}) { + infoLog(func() string { + msg := formatMessage(args...) + return serializeLogMessage(context.Background(), msg) + }) +} + +// Errorc logs an error level message, including context information that is stored in the first parameter. +// If two parameters are supplied, the second must be a message string, and will be logged directly. +// If more than two parameters are supplied, the second parameter must be a format string, and the remaining parameters +// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function. +func Errorc(ctx context.Context, args ...interface{}) { + errorLog(func() string { + msg := formatMessage(args...) + return serializeLogMessage(ctx, msg) + }) +} + +// Errorf logs an error level message. +// If one parameter is supplied, it must be a message string, and will be logged directly. +// If two or more parameters are specified, the first parameter must be a format string, and the remaining parameters +// must be the variables to substitute into the format string, following the convention of the fmt.Sprintf(...) function. +func Errorf(args ...interface{}) { + errorLog(func() string { + msg := formatMessage(args...) + return serializeLogMessage(context.Background(), msg) + }) +} diff --git a/utils/logger/logger_test.go b/utils/logger/logger_test.go new file mode 100644 index 000000000..d7ef9237c --- /dev/null +++ b/utils/logger/logger_test.go @@ -0,0 +1,287 @@ +// this is a new logger interface for mattermost + +package logger + +import ( + "context" + "encoding/json" + "errors" + "fmt" + "regexp" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +type LogMessage struct { + Context map[string]string + File string + Message string +} + +const validPath = `^utils/([a-z_]+/)*logger_test.go$` + +// ensures that the relative path of the file that called into the logger is returned +func TestGetCallerFilename(t *testing.T) { + filename, _ := getCallerFilename() + matched, err := regexp.MatchString(validPath, filename) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that values can be recorded on a Context object, and that the data in question is serialized as a part of the log message +func TestSerializeContext(t *testing.T) { + ctx := context.Background() + + expectedUserId := "some-fake-user-id" + ctx = WithUserId(ctx, expectedUserId) + + expectedRequestId := "some-fake-request-id" + ctx = WithRequestId(ctx, expectedRequestId) + + serialized := serializeContext(ctx) + + assert.Equal(t, map[string]string{ + "user_id": expectedUserId, + "request_id": expectedRequestId, + }, serialized) +} + +// ensures that an entire log message with an empty context can be properly serialized into a JSON object +func TestSerializeLogMessageEmptyContext(t *testing.T) { + emptyContext := context.Background() + + var logMessage = "This is a log message" + var serialized = serializeLogMessage(emptyContext, logMessage) + + var deserialized LogMessage + json.Unmarshal([]byte(serialized), &deserialized) + + assert.Empty(t, deserialized.Context) + assert.Equal(t, logMessage, deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that an entire log message with a populated context can be properly serialized into a JSON object +func TestSerializeLogMessagePopulatedContext(t *testing.T) { + populatedContext := context.Background() + + populatedContext = WithRequestId(populatedContext, "foo") + populatedContext = WithUserId(populatedContext, "bar") + + var logMessage = "This is a log message" + var serialized = serializeLogMessage(populatedContext, logMessage) + + var deserialized LogMessage + json.Unmarshal([]byte(serialized), &deserialized) + + assert.Equal(t, map[string]string{ + "request_id": "foo", + "user_id": "bar", + }, deserialized.Context) + assert.Equal(t, logMessage, deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that a debugLog message is passed through to the underlying logger as expected +func TestDebugc(t *testing.T) { + // inject a "mocked" debugLog method that captures the first argument that is passed to it + var capture string + oldDebug := debugLog + defer func() { debugLog = oldDebug }() + type WrapperType func() string + debugLog = func(format interface{}, args ...interface{}) { + // the code that we're testing passes a closure to the debugLog method, so we have to execute it to get the actual message back + if f, ok := format.(func() string); ok { + capture = WrapperType(f)() + } else { + t.Error("First parameter passed to Debug is not a closure") + } + } + + // log something + emptyContext := context.Background() + var logMessage = "Some log message" + Debugc(emptyContext, logMessage) + + // check to see that the message is logged to the underlying log system, in this case our mock method + var deserialized LogMessage + json.Unmarshal([]byte(capture), &deserialized) + + assert.Empty(t, deserialized.Context) + assert.Equal(t, logMessage, deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that a debugLog message is passed through to the underlying logger as expected +func TestDebugf(t *testing.T) { + // inject a "mocked" debugLog method that captures the first argument that is passed to it + var capture string + oldDebug := debugLog + defer func() { debugLog = oldDebug }() + type WrapperType func() string + debugLog = func(format interface{}, args ...interface{}) { + // the code that we're testing passes a closure to the debugLog method, so we have to execute it to get the actual message back + if f, ok := format.(func() string); ok { + capture = WrapperType(f)() + } else { + t.Error("First parameter passed to Debug is not a closure") + } + } + + // log something + formatString := "Some %v message" + param := "log" + Debugf(formatString, param) + + // check to see that the message is logged to the underlying log system, in this case our mock method + var deserialized LogMessage + json.Unmarshal([]byte(capture), &deserialized) + + assert.Empty(t, deserialized.Context) + assert.Equal(t, fmt.Sprintf(formatString, param), deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that an infoLog message is passed through to the underlying logger as expected +func TestInfoc(t *testing.T) { + // inject a "mocked" infoLog method that captures the first argument that is passed to it + var capture string + oldInfo := infoLog + defer func() { infoLog = oldInfo }() + type WrapperType func() string + infoLog = func(format interface{}, args ...interface{}) { + // the code that we're testing passes a closure to the infoLog method, so we have to execute it to get the actual message back + if f, ok := format.(func() string); ok { + capture = WrapperType(f)() + } else { + t.Error("First parameter passed to Info is not a closure") + } + } + + // log something + emptyContext := context.Background() + var logMessage = "Some log message" + Infoc(emptyContext, logMessage) + + // check to see that the message is logged to the underlying log system, in this case our mock method + var deserialized LogMessage + json.Unmarshal([]byte(capture), &deserialized) + + assert.Empty(t, deserialized.Context) + assert.Equal(t, logMessage, deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that an infoLog message is passed through to the underlying logger as expected +func TestInfof(t *testing.T) { + // inject a "mocked" infoLog method that captures the first argument that is passed to it + var capture string + oldInfo := infoLog + defer func() { infoLog = oldInfo }() + type WrapperType func() string + infoLog = func(format interface{}, args ...interface{}) { + // the code that we're testing passes a closure to the infoLog method, so we have to execute it to get the actual message back + if f, ok := format.(func() string); ok { + capture = WrapperType(f)() + } else { + t.Error("First parameter passed to Info is not a closure") + } + } + + // log something + format := "Some %v message" + param := "log" + Infof(format, param) + + // check to see that the message is logged to the underlying log system, in this case our mock method + var deserialized LogMessage + json.Unmarshal([]byte(capture), &deserialized) + + assert.Empty(t, deserialized.Context) + assert.Equal(t, fmt.Sprintf(format, param), deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that an error message is passed through to the underlying logger as expected +func TestErrorc(t *testing.T) { + // inject a "mocked" err method that captures the first argument that is passed to it + var capture string + oldError := errorLog + defer func() { errorLog = oldError }() + type WrapperType func() string + errorLog = func(format interface{}, args ...interface{}) error { + // the code that we're testing passes a closure to the err method, so we have to execute it to get the actual message back + if f, ok := format.(func() string); ok { + capture = WrapperType(f)() + } else { + t.Error("First parameter passed to Error is not a closure") + } + + // the code under test doesn't care about this return value + return errors.New(capture) + } + + // log something + emptyContext := context.Background() + var logMessage = "Some log message" + Errorc(emptyContext, logMessage) + + // check to see that the message is logged to the underlying log system, in this case our mock method + var deserialized LogMessage + json.Unmarshal([]byte(capture), &deserialized) + + assert.Empty(t, deserialized.Context) + assert.Equal(t, logMessage, deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} + +// ensures that an error message is passed through to the underlying logger as expected +func TestErrorf(t *testing.T) { + // inject a "mocked" err method that captures the first argument that is passed to it + var capture string + oldError := errorLog + defer func() { errorLog = oldError }() + type WrapperType func() string + errorLog = func(format interface{}, args ...interface{}) error { + // the code that we're testing passes a closure to the err method, so we have to execute it to get the actual message back + if f, ok := format.(func() string); ok { + capture = WrapperType(f)() + } else { + t.Error("First parameter passed to Error is not a closure") + } + + // the code under test doesn't care about this return value + return errors.New(capture) + } + + // log something + format := "Some %v message" + param := "log" + Errorf(format, param) + + // check to see that the message is logged to the underlying log system, in this case our mock method + var deserialized LogMessage + json.Unmarshal([]byte(capture), &deserialized) + + assert.Empty(t, deserialized.Context) + assert.Equal(t, fmt.Sprintf(format, param), deserialized.Message) + matched, err := regexp.MatchString(validPath, deserialized.File) + require.NoError(t, err) + assert.True(t, matched) +} -- cgit v1.2.3-1-g7c22