Feature: Add logfmt support to std logger (#550)

log/performance_test.go

@@ -0,0 +1,49 @@
+package log_test
+
+import (
+	"bytes"
+	"fmt"
+	"testing"
+
+	"github.com/beatlabs/patron/log"
+	"github.com/beatlabs/patron/log/std"
+	"github.com/beatlabs/patron/log/zerolog"
+)
+
+func Benchmark_LogFormatsComplex(b *testing.B) {
+	loggers := map[string]log.Logger{
+		"std":     std.New(&bytes.Buffer{}, log.DebugLevel, nil),
+		"zerolog": zerolog.New(&bytes.Buffer{}, log.DebugLevel, nil),
+	}
+
+	for name, logger := range loggers {
+		b.Run(fmt.Sprintf("logger_%s", name), func(b *testing.B) {
+			for i := 0; i < b.N; i++ {
+				subLog := logger.Sub(map[string]interface{}{
+					"string":  "with spaces",
+					"string2": `with "quoted" part`,
+					"string3": "with \n newline",
+					"string4": `with\slashes\`,
+					"simple":  `value`,
+					"integer": 23748,
+				})
+				subLog.Infof(`testing %d\n\t"`, 1)
+			}
+		})
+	}
+}
+
+func Benchmark_LogFormatsSimple(b *testing.B) {
+	loggers := map[string]log.Logger{
+		"std":     std.New(&bytes.Buffer{}, log.DebugLevel, nil),
+		"zerolog": zerolog.New(&bytes.Buffer{}, log.DebugLevel, nil),
+	}
+
+	for name, logger := range loggers {
+		b.Run(fmt.Sprintf("logger_%s", name), func(b *testing.B) {
+			for i := 0; i < b.N; i++ {
+				logger.Infof(`testing %d"`, 1)
+			}
+		})
+	}
+}

log/std/logger.go

@@ -76,7 +76,7 @@ func createFieldsLine(fields map[string]interface{}) string {
 	for _, key := range keys {
 		sb.WriteString(key)
 		sb.WriteRune('=')
-		sb.WriteString(fmt.Sprintf("%v", fields[key]))
+		writeValue(&sb, fmt.Sprintf("%v", fields[key]))
 		sb.WriteRune(' ')
 	}
 
@@ -229,13 +229,59 @@ func (l *Logger) shouldLog(lvl patronLog.Level) bool {
 }
 
 func output(logger *log.Logger, args ...interface{}) string {
-	msg := fmt.Sprint(args...)
-	_ = logger.Output(4, msg)
-	return msg
+	sb := strings.Builder{}
+	writeValue(&sb, fmt.Sprint(args...))
+	_ = logger.Output(4, fmt.Sprintf("message=%s", sb.String()))
+	return sb.String()
 }
 
 func outputf(logger *log.Logger, msg string, args ...interface{}) string {
-	fmtMsg := fmt.Sprintf(msg, args...)
-	_ = logger.Output(4, fmtMsg)
-	return fmtMsg
+	sb := strings.Builder{}
+	writeValue(&sb, fmt.Sprintf(msg, args...))
+	_ = logger.Output(4, fmt.Sprintf("message=%s", sb.String()))
+	return sb.String()
+}
+
+func writeValue(buf *strings.Builder, s string) {
+	needsQuotes := strings.IndexFunc(s, func(r rune) bool {
+		return r <= ' ' || r == '=' || r == '"'
+	}) != -1
+
+	if needsQuotes {
+		buf.WriteByte('"')
+	}
+
+	start := 0
+	for i, r := range s {
+		if r >= 0x20 && r != '\\' && r != '"' {
+			continue
+		}
+
+		if start < i {
+			buf.WriteString(s[start:i])
+		}
+
+		switch r {
+		case '"':
+			buf.WriteString(`\"`)
+		case '\\':
+			buf.WriteString(`\\`)
+		case '\n':
+			buf.WriteString("\\n")
+		case '\r':
+			buf.WriteString("\\r")
+		case '\t':
+			buf.WriteString("\\t")
+		}
+
+		start = i + 1
+	}
+
+	if start < len(s) {
+		buf.WriteString(s[start:])
+	}
+
+	if needsQuotes {
+		buf.WriteByte('"')
+	}
 }

log/std/logger_test.go

@@ -23,7 +23,16 @@ func TestNewLogger(t *testing.T) {
 	assert.Equal(t, log.InfoLevel, logger.Level())
 	assert.Equal(t, logger.fields, map[string]interface{}{"name": "john doe", "age": 18})
 	assert.Contains(t, logger.fieldsLine, "age=18")
-	assert.Contains(t, logger.fieldsLine, "name=john doe")
+	assert.Contains(t, logger.fieldsLine, `name="john doe"`)
+}
+
+func TestLoggerEscapes(t *testing.T) {
+	var b bytes.Buffer
+	logger := New(&b, log.InfoLevel, map[string]interface{}{"name": "john\n doe", "age": 18})
+	assert.Contains(t, logger.fieldsLine, `name="john\n doe"`)
+	logger.Infof(`unescaped "quotes" and \slashes\,
+new lines and	tabs`)
+	assert.Contains(t, b.String(), `name="john\n doe" message="unescaped \"quotes\" and \\slashes\\,\nnew lines and\ttabs"`)
 }
 
 func TestLogMetrics(t *testing.T) {
@@ -75,7 +84,7 @@ func TestNewWithFlagsLogger(t *testing.T) {
 	assert.Equal(t, log.InfoLevel, logger.Level())
 	assert.Equal(t, logger.fields, map[string]interface{}{"name": "john doe", "age": 18})
 	assert.Contains(t, logger.fieldsLine, "age=18")
-	assert.Contains(t, logger.fieldsLine, "name=john doe")
+	assert.Contains(t, logger.fieldsLine, `name="john doe"`)
 	year := time.Now().Format("2006")
 	assert.NotContains(t, logger.fieldsLine, year)
 }
@@ -95,7 +104,7 @@ func TestNewSub(t *testing.T) {
 	assert.Equal(t, log.InfoLevel, subLogger.Level())
 	assert.Equal(t, subLogger.fields, map[string]interface{}{"name": "john doe", "age": 18})
 	assert.Contains(t, subLogger.fieldsLine, "age=18")
-	assert.Contains(t, subLogger.fieldsLine, "name=john doe")
+	assert.Contains(t, subLogger.fieldsLine, `name="john doe"`)
 	subLogger.Info()
 	assert.Contains(t, b.String(), "age=18")
 }
@@ -169,9 +178,9 @@ func TestLogger(t *testing.T) {
 			}
 
 			if tt.args.msg == "" {
-				assert.Contains(t, b.String(), fmt.Sprintf("lvl=%s age=18 name=john doe hello world", levelMap[tt.args.lvl]))
+				assert.Contains(t, b.String(), fmt.Sprintf(`lvl=%s age=18 name="john doe" message="hello world"`, levelMap[tt.args.lvl]))
 			} else {
-				assert.Contains(t, b.String(), fmt.Sprintf("lvl=%s age=18 name=john doe Hi, John", levelMap[tt.args.lvl]))
+				assert.Contains(t, b.String(), fmt.Sprintf(`lvl=%s age=18 name="john doe" message="Hi, John"`, levelMap[tt.args.lvl]))
 			}
 		})
 	}