diff --git a/.travis.yml b/.travis.yml index aebdc35..2f19b4a 100644 --- a/.travis.yml +++ b/.travis.yml @@ -1,9 +1,7 @@ language: go go: - - 1.8.x - 1.9.x - 1.10.x - - tip env: - GOMAXPROCS=4 GORACE=halt_on_error=1 install: diff --git a/entry.go b/entry.go index 29bcae6..82ef93c 100644 --- a/entry.go +++ b/entry.go @@ -83,14 +83,28 @@ func (entry *Entry) WithFields(fields Fields) *Entry { for k, v := range fields { data[k] = v } - return &Entry{Logger: entry.Logger, Data: data} + return &Entry{Logger: entry.Logger, Data: data, Time: entry.Time} +} + +// Overrides the time of the Entry. +func (entry *Entry) WithTime(t time.Time) *Entry { + return &Entry{Logger: entry.Logger, Data: entry.Data, Time: t} } // This function is not declared with a pointer value because otherwise // race conditions will occur when using multiple goroutines func (entry Entry) log(level Level, msg string) { var buffer *bytes.Buffer - entry.Time = time.Now() + + // Default to now, but allow users to override if they want. + // + // We don't have to worry about polluting future calls to Entry#log() + // with this assignment because this function is declared with a + // non-pointer receiver. + if entry.Time.IsZero() { + entry.Time = time.Now() + } + entry.Level = level entry.Message = msg @@ -113,21 +127,19 @@ func (entry Entry) log(level Level, msg string) { } } -// This function is not declared with a pointer value because otherwise -// race conditions will occur when using multiple goroutines -func (entry Entry) fireHooks() { +func (entry *Entry) fireHooks() { entry.Logger.mu.Lock() defer entry.Logger.mu.Unlock() - err := entry.Logger.Hooks.Fire(entry.Level, &entry) + err := entry.Logger.Hooks.Fire(entry.Level, entry) if err != nil { fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) } } func (entry *Entry) write() { - serialized, err := entry.Logger.Formatter.Format(entry) entry.Logger.mu.Lock() defer entry.Logger.mu.Unlock() + serialized, err := entry.Logger.Formatter.Format(entry) if err != nil { fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) } else { diff --git a/exported.go b/exported.go index f2df9e3..7643671 100644 --- a/exported.go +++ b/exported.go @@ -2,6 +2,7 @@ package logrus import ( "io" + "time" ) var ( @@ -15,30 +16,22 @@ func StandardLogger() *Logger { // SetOutput sets the standard logger output. func SetOutput(out io.Writer) { - std.mu.Lock() - defer std.mu.Unlock() - std.Out = out + std.SetOutput(out) } // SetFormatter sets the standard logger formatter. func SetFormatter(formatter Formatter) { - std.mu.Lock() - defer std.mu.Unlock() - std.Formatter = formatter + std.SetFormatter(formatter) } // SetLevel sets the standard logger level. func SetLevel(level Level) { - std.mu.Lock() - defer std.mu.Unlock() std.SetLevel(level) } // GetLevel returns the standard logger level. func GetLevel() Level { - std.mu.Lock() - defer std.mu.Unlock() - return std.level() + return std.GetLevel() } func IsDebugEnabled() bool { @@ -67,9 +60,7 @@ func IsPanicEnabled() bool { // AddHook adds a hook to the standard logger hooks. func AddHook(hook Hook) { - std.mu.Lock() - defer std.mu.Unlock() - std.Hooks.Add(hook) + std.AddHook(hook) } // WithError creates an entry from the standard logger and adds an error to it, using the value defined in ErrorKey as key. @@ -96,6 +87,15 @@ func WithFields(fields Fields) *Entry { return std.WithFields(fields) } +// WithTime creats an entry from the standard logger and overrides the time of +// logs generated with it. +// +// Note that it doesn't log until you call Debug, Print, Info, Warn, Fatal +// or Panic on the Entry it returns. +func WithTime(t time.Time) *Entry { + return std.WithTime(t) +} + // Debug logs a message at level Debug on the standard logger. func Debug(args ...interface{}) { std.Debug(args...) @@ -131,7 +131,7 @@ func Panic(args ...interface{}) { std.Panic(args...) } -// Fatal logs a message at level Fatal on the standard logger. +// Fatal logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatal(args ...interface{}) { std.Fatal(args...) } @@ -171,7 +171,7 @@ func Panicf(format string, args ...interface{}) { std.Panicf(format, args...) } -// Fatalf logs a message at level Fatal on the standard logger. +// Fatalf logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatalf(format string, args ...interface{}) { std.Fatalf(format, args...) } @@ -211,7 +211,7 @@ func Panicln(args ...interface{}) { std.Panicln(args...) } -// Fatalln logs a message at level Fatal on the standard logger. +// Fatalln logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatalln(args ...interface{}) { std.Fatalln(args...) } diff --git a/formatter.go b/formatter.go index 849dc8b..83c7494 100644 --- a/formatter.go +++ b/formatter.go @@ -34,15 +34,18 @@ func prefixFieldClashes(data Fields, fieldMap FieldMap) { timeKey := fieldMap.resolve(FieldKeyTime) if t, ok := data[timeKey]; ok { data["fields."+timeKey] = t + delete(data, timeKey) } msgKey := fieldMap.resolve(FieldKeyMsg) if m, ok := data[msgKey]; ok { data["fields."+msgKey] = m + delete(data, msgKey) } levelKey := fieldMap.resolve(FieldKeyLevel) if l, ok := data[levelKey]; ok { data["fields."+levelKey] = l + delete(data, levelKey) } } diff --git a/hook_test.go b/hook_test.go index 4fea751..80b93b8 100644 --- a/hook_test.go +++ b/hook_test.go @@ -1,10 +1,13 @@ package logrus import ( + "bytes" + "encoding/json" "sync" "testing" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) type TestHook struct { @@ -85,6 +88,46 @@ func TestCanFireMultipleHooks(t *testing.T) { }) } +type SingleLevelModifyHook struct { + ModifyHook +} + +func (h *SingleLevelModifyHook) Levels() []Level { + return []Level{InfoLevel} +} + +func TestHookEntryIsPristine(t *testing.T) { + l := New() + b := &bytes.Buffer{} + l.Formatter = &JSONFormatter{} + l.Out = b + l.AddHook(&SingleLevelModifyHook{}) + + l.Error("error message") + data := map[string]string{} + err := json.Unmarshal(b.Bytes(), &data) + require.NoError(t, err) + _, ok := data["wow"] + require.False(t, ok) + b.Reset() + + l.Info("error message") + data = map[string]string{} + err = json.Unmarshal(b.Bytes(), &data) + require.NoError(t, err) + _, ok = data["wow"] + require.True(t, ok) + b.Reset() + + l.Error("error message") + data = map[string]string{} + err = json.Unmarshal(b.Bytes(), &data) + require.NoError(t, err) + _, ok = data["wow"] + require.False(t, ok) + b.Reset() +} + type ErrorHook struct { Fired bool } diff --git a/hooks/test/test.go b/hooks/test/test.go index 62c4845..234a17d 100644 --- a/hooks/test/test.go +++ b/hooks/test/test.go @@ -15,7 +15,7 @@ type Hook struct { // Entries is an array of all entries that have been received by this hook. // For safe access, use the AllEntries() method, rather than reading this // value directly. - Entries []*logrus.Entry + Entries []logrus.Entry mu sync.RWMutex } @@ -52,7 +52,7 @@ func NewNullLogger() (*logrus.Logger, *Hook) { func (t *Hook) Fire(e *logrus.Entry) error { t.mu.Lock() defer t.mu.Unlock() - t.Entries = append(t.Entries, e) + t.Entries = append(t.Entries, *e) return nil } @@ -68,9 +68,7 @@ func (t *Hook) LastEntry() *logrus.Entry { if i < 0 { return nil } - // Make a copy, for safety - e := *t.Entries[i] - return &e + return &t.Entries[i] } // AllEntries returns all entries that were logged. @@ -79,10 +77,9 @@ func (t *Hook) AllEntries() []*logrus.Entry { defer t.mu.RUnlock() // Make a copy so the returned value won't race with future log requests entries := make([]*logrus.Entry, len(t.Entries)) - for i, entry := range t.Entries { + for i := 0; i < len(t.Entries); i++ { // Make a copy, for safety - e := *entry - entries[i] = &e + entries[i] = &t.Entries[i] } return entries } @@ -91,5 +88,5 @@ func (t *Hook) AllEntries() []*logrus.Entry { func (t *Hook) Reset() { t.mu.Lock() defer t.mu.Unlock() - t.Entries = make([]*logrus.Entry, 0) + t.Entries = make([]logrus.Entry, 0) } diff --git a/hooks/test/test_test.go b/hooks/test/test_test.go index 742be55..d6f6d30 100644 --- a/hooks/test/test_test.go +++ b/hooks/test/test_test.go @@ -1,8 +1,10 @@ package test import ( + "math/rand" "sync" "testing" + "time" "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" @@ -38,24 +40,34 @@ func TestAllHooks(t *testing.T) { } func TestLoggingWithHooksRace(t *testing.T) { + + rand.Seed(time.Now().Unix()) + unlocker := rand.Int() % 100 + assert := assert.New(t) logger, hook := NewNullLogger() - var wg sync.WaitGroup - wg.Add(100) + var wgOne, wgAll sync.WaitGroup + wgOne.Add(1) + wgAll.Add(100) for i := 0; i < 100; i++ { - go func() { + go func(i int) { logger.Info("info") - wg.Done() - }() + wgAll.Done() + if i == unlocker { + wgOne.Done() + } + }(i) } - wg.Wait() + wgOne.Wait() assert.Equal(logrus.InfoLevel, hook.LastEntry().Level) assert.Equal("info", hook.LastEntry().Message) + wgAll.Wait() + entries := hook.AllEntries() assert.Equal(100, len(entries)) } diff --git a/json_formatter.go b/json_formatter.go index 7064947..b13f0cd 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -1,6 +1,7 @@ package logrus import ( + "bytes" "encoding/json" "fmt" ) @@ -33,6 +34,9 @@ type JSONFormatter struct { // DisableTimestamp allows disabling automatic timestamps in output DisableTimestamp bool + // DataKey allows users to put all the log entry parameters into a nested dictionary at a given key. + DataKey string + // FieldMap allows users to customize the names of keys for default fields. // As an example: // formatter := &JSONFormatter{ @@ -58,6 +62,13 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data[k] = v } } + + if f.DataKey != "" { + newData := make(Fields, 4) + newData[f.DataKey] = data + data = newData + } + prefixFieldClashes(data, f.FieldMap) timestampFormat := f.TimestampFormat @@ -71,9 +82,15 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data[f.FieldMap.resolve(FieldKeyMsg)] = entry.Message data[f.FieldMap.resolve(FieldKeyLevel)] = entry.Level.String() - serialized, err := json.Marshal(data) + var b *bytes.Buffer + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } + err := json.NewEncoder(b).Encode(data) if err != nil { return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err) } - return append(serialized, '\n'), nil + return b.Bytes(), nil } diff --git a/json_formatter_test.go b/json_formatter_test.go index 1c140d0..0dde300 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -161,6 +161,48 @@ func TestFieldClashWithRemappedFields(t *testing.T) { } } +func TestFieldsInNestedDictionary(t *testing.T) { + formatter := &JSONFormatter{ + DataKey: "args", + } + + logEntry := WithFields(Fields{ + "level": "level", + "test": "test", + }) + logEntry.Level = InfoLevel + + b, err := formatter.Format(logEntry) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + entry := make(map[string]interface{}) + err = json.Unmarshal(b, &entry) + if err != nil { + t.Fatal("Unable to unmarshal formatted entry: ", err) + } + + args := entry["args"].(map[string]interface{}) + + for _, field := range []string{"test", "level"} { + if value, present := args[field]; !present || value != field { + t.Errorf("Expected field %v to be present under 'args'; untouched", field) + } + } + + for _, field := range []string{"test", "fields.level"} { + if _, present := entry[field]; present { + t.Errorf("Expected field %v not to be present at top level", field) + } + } + + // with nested object, "level" shouldn't clash + if entry["level"] != "info" { + t.Errorf("Expected 'level' field to contain 'info'") + } +} + func TestJSONEntryEndsWithNewline(t *testing.T) { formatter := &JSONFormatter{} diff --git a/logger.go b/logger.go index 034fb18..61bc1cc 100644 --- a/logger.go +++ b/logger.go @@ -5,12 +5,13 @@ import ( "os" "sync" "sync/atomic" + "time" ) type Logger struct { // The logs are `io.Copy`'d to this in a mutex. It's common to set this to a // file, or leave it default which is `os.Stderr`. You can also set this to - // something more adventorous, such as logging to Kafka. + // something more adventurous, such as logging to Kafka. Out io.Writer // Hooks for the logger instance. These allow firing events based on logging // levels and log entries. For example, to send errors to an error tracking @@ -84,11 +85,12 @@ func (logger *Logger) newEntry() *Entry { } func (logger *Logger) releaseEntry(entry *Entry) { + entry.Data = map[string]interface{}{} logger.entryPool.Put(entry) } // Adds a field to the log entry, note that it doesn't log until you call -// Debug, Print, Info, Warn, Fatal or Panic. It only creates a log entry. +// Debug, Print, Info, Warn, Error, Fatal or Panic. It only creates a log entry. // If you want multiple fields, use `WithFields`. func (logger *Logger) WithField(key string, value interface{}) *Entry { entry := logger.newEntry() @@ -112,6 +114,13 @@ func (logger *Logger) WithError(err error) *Entry { return entry.WithError(err) } +// Overrides the time of the log entry. +func (logger *Logger) WithTime(t time.Time) *Entry { + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithTime(t) +} + func (logger *Logger) Debugf(format string, args ...interface{}) { if logger.IsDebugEnabled() { entry := logger.newEntry() @@ -312,10 +321,17 @@ func (logger *Logger) level() Level { return Level(atomic.LoadUint32((*uint32)(&logger.Level))) } +// SetLevel sets the logger level. func (logger *Logger) SetLevel(level Level) { atomic.StoreUint32((*uint32)(&logger.Level), uint32(level)) } +// GetLevel returns the logger level. +func (logger *Logger) GetLevel() Level { + return logger.level() +} + +// AddHook adds a hook to the logger hooks. func (logger *Logger) AddHook(hook Hook) { logger.mu.Lock() defer logger.mu.Unlock() @@ -344,4 +360,25 @@ func (logger *Logger) IsFatalEnabled() bool { func (logger *Logger) IsPanicEnabled() bool { return logger.level() >= PanicLevel +// SetFormatter sets the logger formatter. +func (logger *Logger) SetFormatter(formatter Formatter) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Formatter = formatter +} + +// SetOutput sets the logger output. +func (logger *Logger) SetOutput(output io.Writer) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Out = output +} + +// ReplaceHooks replaces the logger hooks and returns the old ones +func (logger *Logger) ReplaceHooks(hooks LevelHooks) LevelHooks { + logger.mu.Lock() + oldHooks := logger.Hooks + logger.Hooks = hooks + logger.mu.Unlock() + return oldHooks } diff --git a/logger_bench_test.go b/logger_bench_test.go index dd23a35..f0a7684 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -1,6 +1,7 @@ package logrus import ( + "io/ioutil" "os" "testing" ) @@ -59,3 +60,26 @@ func doLoggerBenchmarkNoLock(b *testing.B, out *os.File, formatter Formatter, fi } }) } + +func BenchmarkLoggerJSONFormatter(b *testing.B) { + doLoggerBenchmarkWithFormatter(b, &JSONFormatter{}) +} + +func BenchmarkLoggerTextFormatter(b *testing.B) { + doLoggerBenchmarkWithFormatter(b, &TextFormatter{}) +} + +func doLoggerBenchmarkWithFormatter(b *testing.B, f Formatter) { + b.SetParallelism(100) + log := New() + log.Formatter = f + log.Out = ioutil.Discard + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log. + WithField("foo1", "bar1"). + WithField("foo2", "bar2"). + Info("this is a dummy log") + } + }) +} diff --git a/logrus_test.go b/logrus_test.go index 2c59dc9..4820e33 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -3,10 +3,12 @@ package logrus import ( "bytes" "encoding/json" + "io/ioutil" "strconv" "strings" "sync" "testing" + "time" "github.com/stretchr/testify/assert" ) @@ -209,6 +211,65 @@ func TestDefaultFieldsAreNotPrefixed(t *testing.T) { }) } +func TestWithTimeShouldOverrideTime(t *testing.T) { + now := time.Now().Add(24 * time.Hour) + + LogAndAssertJSON(t, func(log *Logger) { + log.WithTime(now).Info("foobar") + }, func(fields Fields) { + assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat)) + }) +} + +func TestWithTimeShouldNotOverrideFields(t *testing.T) { + now := time.Now().Add(24 * time.Hour) + + LogAndAssertJSON(t, func(log *Logger) { + log.WithField("herp", "derp").WithTime(now).Info("blah") + }, func(fields Fields) { + assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat)) + assert.Equal(t, fields["herp"], "derp") + }) +} + +func TestWithFieldShouldNotOverrideTime(t *testing.T) { + now := time.Now().Add(24 * time.Hour) + + LogAndAssertJSON(t, func(log *Logger) { + log.WithTime(now).WithField("herp", "derp").Info("blah") + }, func(fields Fields) { + assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat)) + assert.Equal(t, fields["herp"], "derp") + }) +} + +func TestTimeOverrideMultipleLogs(t *testing.T) { + var buffer bytes.Buffer + var firstFields, secondFields Fields + + logger := New() + logger.Out = &buffer + formatter := new(JSONFormatter) + formatter.TimestampFormat = time.StampMilli + logger.Formatter = formatter + + llog := logger.WithField("herp", "derp") + llog.Info("foo") + + err := json.Unmarshal(buffer.Bytes(), &firstFields) + assert.NoError(t, err, "should have decoded first message") + + buffer.Reset() + + time.Sleep(10 * time.Millisecond) + llog.Info("bar") + + err = json.Unmarshal(buffer.Bytes(), &secondFields) + assert.NoError(t, err, "should have decoded second message") + + assert.NotEqual(t, firstFields["time"], secondFields["time"], "timestamps should not be equal") +} + func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) { var buffer bytes.Buffer @@ -343,6 +404,45 @@ func TestLoggingRace(t *testing.T) { wg.Wait() } +func TestLoggingRaceWithHooksOnEntry(t *testing.T) { + logger := New() + hook := new(ModifyHook) + logger.AddHook(hook) + entry := logger.WithField("context", "clue") + + var wg sync.WaitGroup + wg.Add(100) + + for i := 0; i < 100; i++ { + go func() { + entry.Info("info") + wg.Done() + }() + } + wg.Wait() +} + +func TestReplaceHooks(t *testing.T) { + old, cur := &TestHook{}, &TestHook{} + + logger := New() + logger.SetOutput(ioutil.Discard) + logger.AddHook(old) + + hooks := make(LevelHooks) + hooks.Add(cur) + replaced := logger.ReplaceHooks(hooks) + + logger.Info("test") + + assert.Equal(t, old.Fired, false) + assert.Equal(t, cur.Fired, true) + + logger.ReplaceHooks(replaced) + logger.Info("test") + assert.Equal(t, old.Fired, true) +} + // Compile test func TestLogrusInterface(t *testing.T) { var buffer bytes.Buffer diff --git a/terminal_bsd.go b/terminal_bsd.go index 4880d13..5b6212d 100644 --- a/terminal_bsd.go +++ b/terminal_bsd.go @@ -1,5 +1,5 @@ // +build darwin freebsd openbsd netbsd dragonfly -// +build !appengine,!gopherjs +// +build !appengine,!js package logrus diff --git a/terminal_check_appengine.go b/terminal_check_appengine.go index 3de08e8..2403de9 100644 --- a/terminal_check_appengine.go +++ b/terminal_check_appengine.go @@ -1,4 +1,4 @@ -// +build appengine gopherjs +// +build appengine package logrus diff --git a/terminal_check_js.go b/terminal_check_js.go new file mode 100644 index 0000000..0c20975 --- /dev/null +++ b/terminal_check_js.go @@ -0,0 +1,11 @@ +// +build js + +package logrus + +import ( + "io" +) + +func checkIfTerminal(w io.Writer) bool { + return false +} diff --git a/terminal_check_notappengine.go b/terminal_check_notappengine.go index 067047a..87f0b80 100644 --- a/terminal_check_notappengine.go +++ b/terminal_check_notappengine.go @@ -1,4 +1,4 @@ -// +build !appengine,!gopherjs +// +build !appengine,!js package logrus diff --git a/terminal_linux.go b/terminal_linux.go index f29a009..634e39b 100644 --- a/terminal_linux.go +++ b/terminal_linux.go @@ -3,7 +3,7 @@ // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. -// +build !appengine,!gopherjs +// +build !appengine,!js package logrus diff --git a/text_formatter.go b/text_formatter.go index ae91edd..4b1f071 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -3,6 +3,7 @@ package logrus import ( "bytes" "fmt" + "os" "sort" "strings" "sync" @@ -35,6 +36,9 @@ type TextFormatter struct { // Force disabling colors. DisableColors bool + // Override coloring based on CLICOLOR and CLICOLOR_FORCE. - https://bixense.com/clicolors/ + EnvironmentOverrideColors bool + // Disable timestamp logging. useful when output is redirected to logging // system that already adds timestamps. DisableTimestamp bool @@ -51,7 +55,6 @@ type TextFormatter struct { // be desired. DisableSorting bool - // Disables the truncation of the level text to 4 characters. DisableLevelTruncation bool @@ -61,6 +64,15 @@ type TextFormatter struct { // Whether the logger's out is to a terminal isTerminal bool + // FieldMap allows users to customize the names of keys for default fields. + // As an example: + // formatter := &TextFormatter{ + // FieldMap: FieldMap{ + // FieldKeyTime: "@timestamp", + // FieldKeyLevel: "@level", + // FieldKeyMsg: "@message"}} + FieldMap FieldMap + sync.Once } @@ -70,9 +82,26 @@ func (f *TextFormatter) init(entry *Entry) { } } +func (f *TextFormatter) isColored() bool { + isColored := f.ForceColors || f.isTerminal + + if f.EnvironmentOverrideColors { + if force, ok := os.LookupEnv("CLICOLOR_FORCE"); ok && force != "0" { + isColored = true + } else if ok && force == "0" { + isColored = false + } else if os.Getenv("CLICOLOR") == "0" { + isColored = false + } + } + + return isColored && !f.DisableColors +} + // Format renders a single log entry func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { - var b *bytes.Buffer + prefixFieldClashes(entry.Data, f.FieldMap) + keys := make([]string, 0, len(entry.Data)) for k := range entry.Data { keys = append(keys, k) @@ -81,31 +110,29 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { if !f.DisableSorting { sort.Strings(keys) } + + var b *bytes.Buffer if entry.Buffer != nil { b = entry.Buffer } else { b = &bytes.Buffer{} } - prefixFieldClashes(entry.Data, emptyFieldMap) - f.Do(func() { f.init(entry) }) - isColored := (f.ForceColors || f.isTerminal) && !f.DisableColors - timestampFormat := f.TimestampFormat if timestampFormat == "" { timestampFormat = defaultTimestampFormat } - if isColored { + if f.isColored() { f.printColored(b, entry, keys, timestampFormat) } else { if !f.DisableTimestamp { - f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) + f.appendKeyValue(b, f.FieldMap.resolve(FieldKeyTime), entry.Time.Format(timestampFormat)) } - f.appendKeyValue(b, "level", entry.Level.String()) + f.appendKeyValue(b, f.FieldMap.resolve(FieldKeyLevel), entry.Level.String()) if entry.Message != "" { - f.appendKeyValue(b, "msg", entry.Message) + f.appendKeyValue(b, f.FieldMap.resolve(FieldKeyMsg), entry.Message) } for _, key := range keys { f.appendKeyValue(b, key, entry.Data[key]) @@ -134,6 +161,10 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin levelText = levelText[0:4] } + // Remove a single newline if it already exists in the message to keep + // the behavior of logrus text_formatter the same as the stdlib log package + entry.Message = strings.TrimSuffix(entry.Message, "\n") + if f.DisableTimestamp { fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m %-44s ", levelColor, levelText, entry.Message) } else if !f.FullTimestamp { diff --git a/text_formatter_test.go b/text_formatter_test.go index fa4321d..b57ef7c 100644 --- a/text_formatter_test.go +++ b/text_formatter_test.go @@ -4,9 +4,12 @@ import ( "bytes" "errors" "fmt" + "os" "strings" "testing" "time" + + "github.com/stretchr/testify/assert" ) func TestFormatting(t *testing.T) { @@ -175,5 +178,273 @@ func TestDisableTimestampWithColoredOutput(t *testing.T) { } } +func TestNewlineBehavior(t *testing.T) { + tf := &TextFormatter{ForceColors: true} + + // Ensure a single new line is removed as per stdlib log + e := NewEntry(StandardLogger()) + e.Message = "test message\n" + b, _ := tf.Format(e) + if bytes.Contains(b, []byte("test message\n")) { + t.Error("first newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected newline to be removed.") + } + + // Ensure a double new line is reduced to a single new line + e = NewEntry(StandardLogger()) + e.Message = "test message\n\n" + b, _ = tf.Format(e) + if bytes.Contains(b, []byte("test message\n\n")) { + t.Error("Double newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected single newline") + } + if !bytes.Contains(b, []byte("test message\n")) { + t.Error("Double newline at end of Entry.Message did not result in a single newline after formatting") + } +} + +func TestTextFormatterFieldMap(t *testing.T) { + formatter := &TextFormatter{ + DisableColors: true, + FieldMap: FieldMap{ + FieldKeyMsg: "message", + FieldKeyLevel: "somelevel", + FieldKeyTime: "timeywimey", + }, + } + + entry := &Entry{ + Message: "oh hi", + Level: WarnLevel, + Time: time.Date(1981, time.February, 24, 4, 28, 3, 100, time.UTC), + Data: Fields{ + "field1": "f1", + "message": "messagefield", + "somelevel": "levelfield", + "timeywimey": "timeywimeyfield", + }, + } + + b, err := formatter.Format(entry) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + assert.Equal(t, + `timeywimey="1981-02-24T04:28:03Z" `+ + `somelevel=warning `+ + `message="oh hi" `+ + `field1=f1 `+ + `fields.message=messagefield `+ + `fields.somelevel=levelfield `+ + `fields.timeywimey=timeywimeyfield`+"\n", + string(b), + "Formatted output doesn't respect FieldMap") +} + +func TestTextFormatterIsColored(t *testing.T) { + params := []struct { + name string + expectedResult bool + isTerminal bool + disableColor bool + forceColor bool + envColor bool + clicolorIsSet bool + clicolorForceIsSet bool + clicolorVal string + clicolorForceVal string + }{ + // Default values + { + name: "testcase1", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output on terminal + { + name: "testcase2", + expectedResult: true, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output on terminal with color disabled + { + name: "testcase3", + expectedResult: false, + isTerminal: true, + disableColor: true, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output not on terminal with color disabled + { + name: "testcase4", + expectedResult: false, + isTerminal: false, + disableColor: true, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output not on terminal with color forced + { + name: "testcase5", + expectedResult: true, + isTerminal: false, + disableColor: false, + forceColor: true, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output on terminal with clicolor set to "0" + { + name: "testcase6", + expectedResult: false, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "0", + }, + // Output on terminal with clicolor set to "1" + { + name: "testcase7", + expectedResult: true, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "1", + }, + // Output not on terminal with clicolor set to "0" + { + name: "testcase8", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "0", + }, + // Output not on terminal with clicolor set to "1" + { + name: "testcase9", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "1", + }, + // Output not on terminal with clicolor set to "1" and force color + { + name: "testcase10", + expectedResult: true, + isTerminal: false, + disableColor: false, + forceColor: true, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "1", + }, + // Output not on terminal with clicolor set to "0" and force color + { + name: "testcase11", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: true, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "0", + }, + // Output not on terminal with clicolor_force set to "1" + { + name: "testcase12", + expectedResult: true, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: false, + clicolorForceIsSet: true, + clicolorForceVal: "1", + }, + // Output not on terminal with clicolor_force set to "0" + { + name: "testcase13", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: false, + clicolorForceIsSet: true, + clicolorForceVal: "0", + }, + // Output on terminal with clicolor_force set to "0" + { + name: "testcase14", + expectedResult: false, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: false, + clicolorForceIsSet: true, + clicolorForceVal: "0", + }, + } + + cleanenv := func() { + os.Unsetenv("CLICOLOR") + os.Unsetenv("CLICOLOR_FORCE") + } + + defer cleanenv() + + for _, val := range params { + t.Run("textformatter_"+val.name, func(subT *testing.T) { + tf := TextFormatter{ + isTerminal: val.isTerminal, + DisableColors: val.disableColor, + ForceColors: val.forceColor, + EnvironmentOverrideColors: val.envColor, + } + cleanenv() + if val.clicolorIsSet { + os.Setenv("CLICOLOR", val.clicolorVal) + } + if val.clicolorForceIsSet { + os.Setenv("CLICOLOR_FORCE", val.clicolorForceVal) + } + res := tf.isColored() + assert.Equal(subT, val.expectedResult, res) + }) + } +} + // TODO add tests for sorting etc., this requires a parser for the text // formatter output.