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

api4/channel_test.go

@@ -502,9 +502,7 @@ func TestGetDeletedChannelsForTeam(t *testing.T) {
 
 	channels, resp = Client.GetDeletedChannelsForTeam(team.Id, 0, 100, "")
 	CheckNoError(t, resp)
-	if len(channels) != 0 {
+	numInitialChannelsForTeam := len(channels)
-		t.Fatal("should be no deleted channels")
-	}
 
 	// create and delete public channel
 	publicChannel1 := th.CreatePublicChannel()
@@ -512,7 +510,7 @@ func TestGetDeletedChannelsForTeam(t *testing.T) {
 
 	channels, resp = Client.GetDeletedChannelsForTeam(team.Id, 0, 100, "")
 	CheckNoError(t, resp)
-	if len(channels) != 1 {
+	if len(channels) != numInitialChannelsForTeam+1 {
 		t.Fatal("should be 1 deleted channel")
 	}
 
@@ -521,7 +519,7 @@ func TestGetDeletedChannelsForTeam(t *testing.T) {
 
 	channels, resp = Client.GetDeletedChannelsForTeam(team.Id, 0, 100, "")
 	CheckNoError(t, resp)
-	if len(channels) != 2 {
+	if len(channels) != numInitialChannelsForTeam+2 {
 		t.Fatal("should be 2 deleted channels")
 	}
 

utils/config.go

@@ -123,6 +123,8 @@ func ConfigureCmdLineLog() {
 	configureLog(&ls)
 }
 
+// TODO: this code initializes console and file logging. It will eventually be replaced by JSON logging in logger/logger.go
+// See PLT-3893 for more information
 func configureLog(s *model.LogSettings) {
 
 	l4g.Close()

utils/config_test.go

@@ -83,29 +83,27 @@ func TestRedirectStdLog(t *testing.T) {
 }
 
 func TestAddRemoveConfigListener(t *testing.T) {
-	if len(cfgListeners) != 0 {
+	numIntitialCfgListeners := len(cfgListeners)
-		t.Fatal("should've started with 0 listeners")
-	}
 
 	id1 := AddConfigListener(func(*model.Config, *model.Config) {
 	})
-	if len(cfgListeners) != 1 {
+	if len(cfgListeners) != numIntitialCfgListeners+1 {
 		t.Fatal("should now have 1 listener")
 	}
 
 	id2 := AddConfigListener(func(*model.Config, *model.Config) {
 	})
-	if len(cfgListeners) != 2 {
+	if len(cfgListeners) != numIntitialCfgListeners+2 {
 		t.Fatal("should now have 2 listeners")
 	}
 
 	RemoveConfigListener(id1)
-	if len(cfgListeners) != 1 {
+	if len(cfgListeners) != numIntitialCfgListeners+1 {
 		t.Fatal("should've removed first listener")
 	}
 
 	RemoveConfigListener(id2)
-	if len(cfgListeners) != 0 {
+	if len(cfgListeners) != numIntitialCfgListeners {
 		t.Fatal("should've removed both listeners")
 	}
 }

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

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

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