Merge pull request #60 from aybabtme/fix-duplicate-keys

fix duplication of msg/time/level keys, add benchmarks.

entry.go

@@ -76,12 +76,12 @@ func (entry *Entry) log(level Level, msg string) string {
 	entry.Message = msg
 
 	if err := entry.Logger.Hooks.Fire(level, entry); err != nil {
-		fmt.Fprintf(os.Stderr, "Failed to fire hook", err)
+		fmt.Fprintf(os.Stderr, "Failed to fire hook\n", err)
 	}
 
 	reader, err := entry.Reader()
 	if err != nil {
-		fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v", err)
+		fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err)
 	}
 
 	entry.Logger.mu.Lock()
@@ -89,7 +89,7 @@ func (entry *Entry) log(level Level, msg string) string {
 
 	_, err = io.Copy(entry.Logger.Out, reader)
 	if err != nil {
-		fmt.Fprintf(os.Stderr, "Failed to write to log, %v", err)
+		fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err)
 	}
 
 	return reader.String()

formatter.go

@@ -1,9 +1,5 @@
 package logrus
 
-import (
-	"time"
-)
-
 // The Formatter interface is used to implement a custom Formatter. It takes an
 // `Entry`. It exposes all the fields, including the default ones:
 //
@@ -36,19 +32,13 @@ func prefixFieldClashes(entry *Entry) {
 		entry.Data["fields.time"] = entry.Data["time"]
 	}
 
-	entry.Data["time"] = entry.Time.Format(time.RFC3339)
-
 	_, ok = entry.Data["msg"]
 	if ok {
 		entry.Data["fields.msg"] = entry.Data["msg"]
 	}
 
-	entry.Data["msg"] = entry.Message
-
 	_, ok = entry.Data["level"]
 	if ok {
 		entry.Data["fields.level"] = entry.Data["level"]
 	}
-
-	entry.Data["level"] = entry.Level.String()
 }

formatter_bench_test.go

@@ -0,0 +1,88 @@
+package logrus
+
+import (
+	"testing"
+	"time"
+)
+
+// smallFields is a small size data set for benchmarking
+var smallFields = Fields{
+	"foo":   "bar",
+	"baz":   "qux",
+	"one":   "two",
+	"three": "four",
+}
+
+// largeFields is a large size data set for benchmarking
+var largeFields = Fields{
+	"foo":       "bar",
+	"baz":       "qux",
+	"one":       "two",
+	"three":     "four",
+	"five":      "six",
+	"seven":     "eight",
+	"nine":      "ten",
+	"eleven":    "twelve",
+	"thirteen":  "fourteen",
+	"fifteen":   "sixteen",
+	"seventeen": "eighteen",
+	"nineteen":  "twenty",
+	"a":         "b",
+	"c":         "d",
+	"e":         "f",
+	"g":         "h",
+	"i":         "j",
+	"k":         "l",
+	"m":         "n",
+	"o":         "p",
+	"q":         "r",
+	"s":         "t",
+	"u":         "v",
+	"w":         "x",
+	"y":         "z",
+	"this":      "will",
+	"make":      "thirty",
+	"entries":   "yeah",
+}
+
+func BenchmarkSmallTextFormatter(b *testing.B) {
+	doBenchmark(b, &TextFormatter{DisableColors: true}, smallFields)
+}
+
+func BenchmarkLargeTextFormatter(b *testing.B) {
+	doBenchmark(b, &TextFormatter{DisableColors: true}, largeFields)
+}
+
+func BenchmarkSmallColoredTextFormatter(b *testing.B) {
+	doBenchmark(b, &TextFormatter{ForceColors: true}, smallFields)
+}
+
+func BenchmarkLargeColoredTextFormatter(b *testing.B) {
+	doBenchmark(b, &TextFormatter{ForceColors: true}, largeFields)
+}
+
+func BenchmarkSmallJSONFormatter(b *testing.B) {
+	doBenchmark(b, &JSONFormatter{}, smallFields)
+}
+
+func BenchmarkLargeJSONFormatter(b *testing.B) {
+	doBenchmark(b, &JSONFormatter{}, largeFields)
+}
+
+func doBenchmark(b *testing.B, formatter Formatter, fields Fields) {
+	entry := &Entry{
+		Time:    time.Time{},
+		Level:   InfoLevel,
+		Message: "message",
+		Data:    fields,
+	}
+	var d []byte
+	var err error
+	for i := 0; i < b.N; i++ {
+		d, err = formatter.Format(entry)
+		if err != nil {
+			b.Fatal(err)
+		}
+		b.SetBytes(int64(len(d)))
+	}
+}

json_formatter.go

@@ -3,13 +3,16 @@ package logrus
 import (
 	"encoding/json"
 	"fmt"
+	"time"
 )
 
-type JSONFormatter struct {
+type JSONFormatter struct{}
-}
 
 func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
 	prefixFieldClashes(entry)
+	entry.Data["time"] = entry.Time.Format(time.RFC3339)
+	entry.Data["msg"] = entry.Message
+	entry.Data["level"] = entry.Level.String()
 
 	serialized, err := json.Marshal(entry.Data)
 	if err != nil {

logrus_test.go

@@ -3,6 +3,8 @@ package logrus
 import (
 	"bytes"
 	"encoding/json"
+	"strconv"
+	"strings"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -24,6 +26,31 @@ func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fi
 	assertions(fields)
 }
 
+func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields map[string]string)) {
+	var buffer bytes.Buffer
+
+	logger := New()
+	logger.Out = &buffer
+	logger.Formatter = &TextFormatter{
+		DisableColors: true,
+	}
+
+	log(logger)
+
+	fields := make(map[string]string)
+	for _, kv := range strings.Split(buffer.String(), " ") {
+		if !strings.Contains(kv, "=") {
+			continue
+		}
+		kvArr := strings.Split(kv, "=")
+		key := strings.TrimSpace(kvArr[0])
+		val, err := strconv.Unquote(kvArr[1])
+		assert.NoError(t, err)
+		fields[key] = val
+	}
+	assertions(fields)
+}
+
 func TestPrint(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Print("test")
@@ -163,6 +190,20 @@ func TestUserSuppliedLevelFieldHasPrefix(t *testing.T) {
 	})
 }
 
+func TestDefaultFieldsAreNotPrefixed(t *testing.T) {
+	LogAndAssertText(t, func(log *Logger) {
+		ll := log.WithField("herp", "derp")
+		ll.Info("hello")
+		ll.Info("bye")
+	}, func(fields map[string]string) {
+		for _, fieldName := range []string{"fields.level", "fields.time", "fields.msg"} {
+			if _, ok := fields[fieldName]; ok {
+				t.Fatalf("should not have prefixed %q: %v", fieldName, fields)
+			}
+		}
+	})
+}
+
 func TestConvertLevelToString(t *testing.T) {
 	assert.Equal(t, "debug", DebugLevel.String())
 	assert.Equal(t, "info", InfoLevel.String())

text_formatter.go

@@ -38,45 +38,26 @@ type TextFormatter struct {
 
 func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
 
+	var keys []string
+	for k := range entry.Data {
+		keys = append(keys, k)
+	}
+	sort.Strings(keys)
+
 	b := &bytes.Buffer{}
 
 	prefixFieldClashes(entry)
 
-	if (f.ForceColors || isTerminal) && !f.DisableColors {
+	isColored := (f.ForceColors || isTerminal) && !f.DisableColors
-		levelText := strings.ToUpper(entry.Data["level"].(string))[0:4]
 
-		levelColor := blue
+	if isColored {
-
+		printColored(b, entry, keys)
-		if entry.Data["level"] == "warning" {
-			levelColor = yellow
-		} else if entry.Data["level"] == "error" ||
-			entry.Data["level"] == "fatal" ||
-			entry.Data["level"] == "panic" {
-			levelColor = red
-		}
-
-		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, miniTS(), entry.Data["msg"])
-
-		var keys []string
-		for k := range entry.Data {
-			if k != "level" && k != "time" && k != "msg" {
-				keys = append(keys, k)
-			}
-		}
-		sort.Strings(keys)
-		for _, k := range keys {
-			v := entry.Data[k]
-			fmt.Fprintf(b, " \x1b[%dm%s\x1b[0m=%v", levelColor, k, v)
-		}
 	} else {
-		f.AppendKeyValue(b, "time", entry.Data["time"].(string))
+		f.AppendKeyValue(b, "time", entry.Time.Format(time.RFC3339))
-		f.AppendKeyValue(b, "level", entry.Data["level"].(string))
+		f.AppendKeyValue(b, "level", entry.Level.String())
-		f.AppendKeyValue(b, "msg", entry.Data["msg"].(string))
+		f.AppendKeyValue(b, "msg", entry.Message)
-
+		for _, key := range keys {
-		for key, value := range entry.Data {
+			f.AppendKeyValue(b, key, entry.Data[key])
-			if key != "time" && key != "level" && key != "msg" {
-				f.AppendKeyValue(b, key, value)
-			}
 		}
 	}
 
@@ -84,6 +65,26 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
 	return b.Bytes(), nil
 }
 
+func printColored(b *bytes.Buffer, entry *Entry, keys []string) {
+	var levelColor int
+	switch entry.Level {
+	case WarnLevel:
+		levelColor = yellow
+	case ErrorLevel, FatalLevel, PanicLevel:
+		levelColor = red
+	default:
+		levelColor = blue
+	}
+
+	levelText := strings.ToUpper(entry.Level.String())[0:4]
+
+	fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, miniTS(), entry.Message)
+	for _, k := range keys {
+		v := entry.Data[k]
+		fmt.Fprintf(b, " \x1b[%dm%s\x1b[0m=%v", levelColor, k, v)
+	}
+}
+
 func (f *TextFormatter) AppendKeyValue(b *bytes.Buffer, key, value interface{}) {
 	if _, ok := value.(string); ok {
 		fmt.Fprintf(b, "%v=%q ", key, value)