From c4cc714937a366b4c1fe44bbbf88041c4d6b1382 Mon Sep 17 00:00:00 2001 From: Antoine Grondin Date: Tue, 16 Sep 2014 20:19:42 -0400 Subject: [PATCH 1/2] fix duplication of msg/time/level keys, add benchmarks. --- entry.go | 6 +-- formatter.go | 10 ----- formatter_bench_test.go | 88 +++++++++++++++++++++++++++++++++++++++++ json_formatter.go | 7 +++- text_formatter.go | 67 +++++++++++++++---------------- 5 files changed, 130 insertions(+), 48 deletions(-) create mode 100644 formatter_bench_test.go diff --git a/entry.go b/entry.go index 58eb263..626f564 100644 --- a/entry.go +++ b/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() diff --git a/formatter.go b/formatter.go index fc0ebd7..cccf1c2 100644 --- a/formatter.go +++ b/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() } diff --git a/formatter_bench_test.go b/formatter_bench_test.go new file mode 100644 index 0000000..77989da --- /dev/null +++ b/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))) + } +} diff --git a/json_formatter.go b/json_formatter.go index c0e2d18..9d11b64 100644 --- a/json_formatter.go +++ b/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 { diff --git a/text_formatter.go b/text_formatter.go index 0f38c45..2ab0139 100644 --- a/text_formatter.go +++ b/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 { - levelText := strings.ToUpper(entry.Data["level"].(string))[0:4] + isColored := (f.ForceColors || isTerminal) && !f.DisableColors - levelColor := blue - - 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) - } + if isColored { + printColored(b, entry, keys) } else { - f.AppendKeyValue(b, "time", entry.Data["time"].(string)) - f.AppendKeyValue(b, "level", entry.Data["level"].(string)) - f.AppendKeyValue(b, "msg", entry.Data["msg"].(string)) - - for key, value := range entry.Data { - if key != "time" && key != "level" && key != "msg" { - f.AppendKeyValue(b, key, value) - } + f.AppendKeyValue(b, "time", entry.Time.Format(time.RFC3339)) + f.AppendKeyValue(b, "level", entry.Level.String()) + f.AppendKeyValue(b, "msg", entry.Message) + for _, key := range keys { + f.AppendKeyValue(b, key, entry.Data[key]) } } @@ -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) From dc01f6d5978b1ba864f7e7337d27979430d09705 Mon Sep 17 00:00:00 2001 From: Antoine Grondin Date: Sun, 21 Sep 2014 13:16:35 -0400 Subject: [PATCH 2/2] add regression for basic fields being incorrectly prefixed --- logrus_test.go | 41 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 41 insertions(+) diff --git a/logrus_test.go b/logrus_test.go index 6202300..53dec59 100644 --- a/logrus_test.go +++ b/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())