feat(logger): Expand LogConsumer interface to have explicit field mapping. (#147)

* Updates the LogConsumer interface to accept a fields map[string]interface{}
* Moves message formatting into the the LogConsumer implementation
* Parameterize io.Writer in the default LogConsumer to facilitate testing

Author: Mike Davis

pkg/logging/interface.go

@@ -19,7 +19,7 @@ package logging
 
 // OptimizelyLogConsumer consumes log messages produced by the log producers
 type OptimizelyLogConsumer interface {
-	Log(level LogLevel, message string)
+	Log(level LogLevel, message string, fields map[string]interface{})
 	SetLogLevel(logLevel LogLevel)
 }
 

pkg/logging/level_log_consumer.go

@@ -18,8 +18,9 @@
 package logging
 
 import (
+	"fmt"
+	"io"
 	"log"
-	"os"
 )
 
 // FilteredLevelLogConsumer is an implementation of the OptimizelyLogConsumer that filters by log level
@@ -29,8 +30,10 @@ type FilteredLevelLogConsumer struct {
 }
 
 // Log logs the message if it's log level is higher than or equal to the logger's set level
-func (l *FilteredLevelLogConsumer) Log(level LogLevel, message string) {
+func (l *FilteredLevelLogConsumer) Log(level LogLevel, message string, fields map[string]interface{}) {
 	if l.level <= level {
+		// prepends the name and log level to the message
+		message = fmt.Sprintf("[%s][%s] %s", level, fields["name"], message)
 		l.logger.Println(message)
 	}
 }
@@ -40,10 +43,10 @@ func (l *FilteredLevelLogConsumer) SetLogLevel(level LogLevel) {
 	l.level = level
 }
 
-// NewStdoutFilteredLevelLogConsumer returns a new logger that logs to stdout
-func NewStdoutFilteredLevelLogConsumer(level LogLevel) *FilteredLevelLogConsumer {
+// NewFilteredLevelLogConsumer returns a new logger that logs to stdout
+func NewFilteredLevelLogConsumer(level LogLevel, out io.Writer) *FilteredLevelLogConsumer {
 	return &FilteredLevelLogConsumer{
 		level:  level,
-		logger: log.New(os.Stdout, "[Optimizely]", log.LstdFlags),
+		logger: log.New(out, "[Optimizely]", log.LstdFlags),
 	}
 }

pkg/logging/level_log_consumer_test.go

@@ -17,20 +17,38 @@
 package logging
 
 import (
+	"bytes"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
 )
 
-func TestNewStdoutFilteredLevelLogConsumer(t *testing.T) {
-	newLogger := NewStdoutFilteredLevelLogConsumer(LogLevelInfo)
+func TestFilteredLogging(t *testing.T) {
+	out := &bytes.Buffer{}
+	newLogger := NewFilteredLevelLogConsumer(LogLevelInfo, out)
 
 	assert.Equal(t, newLogger.level, LogLevel(2))
 	assert.NotNil(t, newLogger.logger)
 
 	newLogger.SetLogLevel(3)
 	assert.Equal(t, newLogger.level, LogLevel(3))
 
-	newLogger.Log(1, "this is hidden")
-	newLogger.Log(4, "this is visible")
+	newLogger.Log(1, "this is hidden", map[string]interface{}{})
+	assert.Equal(t, "", out.String())
+	out.Reset()
+
+	newLogger.Log(4, "this is visible", map[string]interface{}{})
+	assert.Contains(t, out.String(), "this is visible")
+	out.Reset()
+}
+
+func TestLogFormatting(t *testing.T) {
+	out := &bytes.Buffer{}
+	newLogger := NewFilteredLevelLogConsumer(LogLevelInfo, out)
+
+	newLogger.Log(LogLevelInfo, "test message", map[string]interface{}{"name": "test-name"})
+	assert.Contains(t, out.String(), "test message")
+	assert.Contains(t, out.String(), "[Info]")
+	assert.Contains(t, out.String(), "[test-name]")
+	assert.Contains(t, out.String(), "[Optimizely]")
 }

pkg/logging/logger.go

@@ -17,7 +17,10 @@
 // Package logging //
 package logging
 
-import "fmt"
+import (
+	"fmt"
+	"os"
+)
 
 // LogLevel represents the level of the log (i.e. Debug, Info, Warning, Error)
 type LogLevel int
@@ -43,7 +46,7 @@ const (
 )
 
 func init() {
-	defaultLogConsumer = NewStdoutFilteredLevelLogConsumer(LogLevelInfo)
+	defaultLogConsumer = NewFilteredLevelLogConsumer(LogLevelInfo, os.Stdout)
 }
 
 // SetLogger replaces the default logger with the given logger
@@ -59,13 +62,13 @@ func SetLogLevel(logLevel LogLevel) {
 // GetLogger returns a log producer with the given name
 func GetLogger(name string) OptimizelyLogProducer {
 	return NamedLogProducer{
-		name: name,
+		fields: map[string]interface{}{"name": name},
 	}
 }
 
 // NamedLogProducer produces logs prefixed with its name
 type NamedLogProducer struct {
-	name string
+	fields map[string]interface{}
 }
 
 // Debug logs the given message with a DEBUG level
@@ -86,14 +89,11 @@ func (p NamedLogProducer) Warning(message string) {
 // Error logs the given message with a ERROR level
 func (p NamedLogProducer) Error(message string, err interface{}) {
 	if err != nil {
-		message = fmt.Sprintf("%s %v", message, err)
+		message = fmt.Sprintf("%s: %v", message, err)
 	}
 	p.log(LogLevelError, message)
 }
 
 func (p NamedLogProducer) log(logLevel LogLevel, message string) {
-
-	// prepends the name and log level to the message
-	message = fmt.Sprintf("[%s][%s] %s", p.name, logLevel, message)
-	defaultLogConsumer.Log(logLevel, message)
+	defaultLogConsumer.Log(logLevel, message, p.fields)
 }

pkg/logging/logger_test.go

@@ -29,8 +29,8 @@ type MockOptimizelyLogger struct {
 	loggedMessages []string
 }
 
-func (m *MockOptimizelyLogger) Log(level LogLevel, message string) {
-	m.Called(level, message)
+func (m *MockOptimizelyLogger) Log(level LogLevel, message string, fields map[string]interface{}) {
+	m.Called(level, message, fields["name"])
 	m.loggedMessages = append(m.loggedMessages, message)
 }
 
@@ -40,56 +40,67 @@ func (m *MockOptimizelyLogger) SetLogLevel(level LogLevel) {
 
 func TestNamedLoggerDebug(t *testing.T) {
 	testLogMessage := "Test debug message"
-	expectedLogMessage := "[test-debug][Debug] Test debug message"
+	testLogName := "test-debug"
 	testLogger := new(MockOptimizelyLogger)
-	testLogger.On("Log", LogLevelDebug, expectedLogMessage)
+	testLogger.On("Log", LogLevelDebug, testLogMessage, testLogName)
 
 	SetLogger(testLogger)
 
-	logProducer := GetLogger("test-debug")
+	logProducer := GetLogger(testLogName)
 	logProducer.Debug(testLogMessage)
 	testLogger.AssertExpectations(t)
-	assert.Equal(t, []string{expectedLogMessage}, testLogger.loggedMessages)
+	assert.Equal(t, []string{testLogMessage}, testLogger.loggedMessages)
 }
 
 func TestNamedLoggerInfo(t *testing.T) {
 	testLogMessage := "Test info message"
-	expectedLogMessage := "[test-info][Info] Test info message"
+	testLogName := "test-info"
 	testLogger := new(MockOptimizelyLogger)
-	testLogger.On("Log", LogLevelInfo, expectedLogMessage)
+	testLogger.On("Log", LogLevelInfo, testLogMessage, testLogName)
 
 	SetLogger(testLogger)
 
-	logProducer := GetLogger("test-info")
+	logProducer := GetLogger(testLogName)
 	logProducer.Info(testLogMessage)
 	testLogger.AssertExpectations(t)
-	assert.Equal(t, []string{expectedLogMessage}, testLogger.loggedMessages)
+	assert.Equal(t, []string{testLogMessage}, testLogger.loggedMessages)
 }
 
 func TestNamedLoggerWarning(t *testing.T) {
 	testLogMessage := "Test warn message"
-	expectedLogMessage := "[test-warn][Warning] Test warn message"
+	testLogName := "test-warn"
 	testLogger := new(MockOptimizelyLogger)
-	testLogger.On("Log", LogLevelWarning, expectedLogMessage)
+	testLogger.On("Log", LogLevelWarning, testLogMessage, testLogName)
 
 	SetLogger(testLogger)
 
-	logProducer := GetLogger("test-warn")
+	logProducer := GetLogger(testLogName)
 	logProducer.Warning(testLogMessage)
 	testLogger.AssertExpectations(t)
-	assert.Equal(t, []string{expectedLogMessage}, testLogger.loggedMessages)
+	assert.Equal(t, []string{testLogMessage}, testLogger.loggedMessages)
 }
 
 func TestNamedLoggerError(t *testing.T) {
 	testLogMessage := "Test error message"
-	expectedLogMessage := "[test-error][Error] Test error message I am an error object"
+	testLogName := "test-error"
+	expectedLogMessage := "Test error message: I am an error object"
 	testLogger := new(MockOptimizelyLogger)
-	testLogger.On("Log", LogLevelError, expectedLogMessage)
+	testLogger.On("Log", LogLevelError, expectedLogMessage, testLogName)
 	SetLogger(testLogger)
 
 	err := errors.New("I am an error object")
-	logProducer := GetLogger("test-error")
+	logProducer := GetLogger(testLogName)
 	logProducer.Error(testLogMessage, err)
 	testLogger.AssertExpectations(t)
 	assert.Equal(t, []string{expectedLogMessage}, testLogger.loggedMessages)
 }
+
+func TestSetLogLevel(t *testing.T) {
+	testLogger := new(MockOptimizelyLogger)
+	testLogger.On("SetLogLevel", LogLevelError)
+
+	SetLogger(testLogger)
+	SetLogLevel(LogLevelError)
+
+	testLogger.AssertExpectations(t)
+}