diff --git a/.gitignore b/.gitignore index 66be63a..6b7d7d1 100644 --- a/.gitignore +++ b/.gitignore @@ -1 +1,2 @@ logrus +vendor diff --git a/.travis.yml b/.travis.yml index aebdc35..1f953be 100644 --- a/.travis.yml +++ b/.travis.yml @@ -1,15 +1,51 @@ language: go -go: - - 1.8.x - - 1.9.x - - 1.10.x - - tip env: - GOMAXPROCS=4 GORACE=halt_on_error=1 -install: - - go get github.com/stretchr/testify/assert - - go get gopkg.in/gemnasium/logrus-airbrake-hook.v2 - - go get golang.org/x/sys/unix - - go get golang.org/x/sys/windows -script: - - go test -race -v ./... +matrix: + include: + - go: 1.10.x + install: + - go get github.com/stretchr/testify/assert + - go get golang.org/x/crypto/ssh/terminal + - go get golang.org/x/sys/unix + - go get golang.org/x/sys/windows + script: + - go test -race -v ./... + - go: 1.11.x + env: GO111MODULE=on + install: + - go mod download + script: + - go test -race -v ./... + - go: 1.11.x + env: GO111MODULE=off + install: + - go get github.com/stretchr/testify/assert + - go get golang.org/x/crypto/ssh/terminal + - go get golang.org/x/sys/unix + - go get golang.org/x/sys/windows + script: + - go test -race -v ./... + - go: 1.10.x + install: + - go get github.com/stretchr/testify/assert + - go get golang.org/x/crypto/ssh/terminal + - go get golang.org/x/sys/unix + - go get golang.org/x/sys/windows + script: + - go test -race -v -tags appengine ./... + - go: 1.11.x + env: GO111MODULE=on + install: + - go mod download + script: + - go test -race -v -tags appengine ./... + - go: 1.11.x + env: GO111MODULE=off + install: + - go get github.com/stretchr/testify/assert + - go get golang.org/x/crypto/ssh/terminal + - go get golang.org/x/sys/unix + - go get golang.org/x/sys/windows + script: + - go test -race -v -tags appengine ./... diff --git a/CHANGELOG.md b/CHANGELOG.md index 1bd1deb..cb85d9f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,45 @@ +# 1.2.0 +This new release introduces: + * A new method `SetReportCaller` in the `Logger` to enable the file, line and calling function from which the trace has been issued + * A new trace level named `Trace` whose level is below `Debug` + * A configurable exit function to be called upon a Fatal trace + * The `Level` object now implements `encoding.TextUnmarshaler` interface + +# 1.1.1 +This is a bug fix release. + * fix the build break on Solaris + * don't drop a whole trace in JSONFormatter when a field param is a function pointer which can not be serialized + +# 1.1.0 +This new release introduces: + * several fixes: + * a fix for a race condition on entry formatting + * proper cleanup of previously used entries before putting them back in the pool + * the extra new line at the end of message in text formatter has been removed + * a new global public API to check if a level is activated: IsLevelEnabled + * the following methods have been added to the Logger object + * IsLevelEnabled + * SetFormatter + * SetOutput + * ReplaceHooks + * introduction of go module + * an indent configuration for the json formatter + * output colour support for windows + * the field sort function is now configurable for text formatter + * the CLICOLOR and CLICOLOR\_FORCE environment variable support in text formater + +# 1.0.6 + +This new release introduces: + * a new api WithTime which allows to easily force the time of the log entry + which is mostly useful for logger wrapper + * a fix reverting the immutability of the entry given as parameter to the hooks + a new configuration field of the json formatter in order to put all the fields + in a nested dictionnary + * a new SetOutput method in the Logger + * a new configuration of the textformatter to configure the name of the default keys + * a new configuration of the text formatter to disable the level truncation + # 1.0.5 * Fix hooks race (#707) diff --git a/README.md b/README.md index 072e99b..3987310 100644 --- a/README.md +++ b/README.md @@ -56,8 +56,39 @@ time="2015-03-26T01:27:38-04:00" level=warning msg="The group's number increased time="2015-03-26T01:27:38-04:00" level=debug msg="Temperature changes" temperature=-4 time="2015-03-26T01:27:38-04:00" level=panic msg="It's over 9000!" animal=orca size=9009 time="2015-03-26T01:27:38-04:00" level=fatal msg="The ice breaks!" err=&{0x2082280c0 map[animal:orca size:9009] 2015-03-26 01:27:38.441574009 -0400 EDT panic It's over 9000!} number=100 omg=true -exit status 1 ``` +To ensure this behaviour even if a TTY is attached, set your formatter as follows: + +```go + log.SetFormatter(&log.TextFormatter{ + DisableColors: true, + FullTimestamp: true, + }) +``` + +#### Logging Method Name + +If you wish to add the calling method as a field, instruct the logger via: +```go +log.SetReportCaller(true) +``` +This adds the caller as 'method' like so: + +```json +{"animal":"penguin","level":"fatal","method":"github.com/sirupsen/arcticcreatures.migrate","msg":"a penguin swims by", +"time":"2014-03-10 19:57:38.562543129 -0400 EDT"} +``` + +```text +time="2015-03-26T01:27:38-04:00" level=fatal method=github.com/sirupsen/arcticcreatures.migrate msg="a penguin swims by" animal=penguin +``` +Note that this does add measurable overhead - the cost will depend on the version of Go, but is +between 20 and 40% in recent tests with 1.6 and 1.7. You can validate this in your +environment via benchmarks: +``` +go test -bench=.*CallerTracing +``` + #### Case-sensitivity @@ -246,9 +277,10 @@ A list of currently known of service hook can be found in this wiki [page](https #### Level logging -Logrus has six logging levels: Debug, Info, Warning, Error, Fatal and Panic. +Logrus has seven logging levels: Trace, Debug, Info, Warning, Error, Fatal and Panic. ```go +log.Trace("Something very low level.") log.Debug("Useful debugging information.") log.Info("Something noteworthy happened!") log.Warn("You should probably take a look at this.") @@ -329,6 +361,7 @@ The built-in logging formatters are: Third party logging formatters: * [`FluentdFormatter`](https://github.com/joonix/log). Formats entries that can be parsed by Kubernetes and Google Container Engine. +* [`GELF`](https://github.com/fabienm/go-logrus-formatters). Formats entries so they comply to Graylog's [GELF 1.1 specification](http://docs.graylog.org/en/2.4/pages/gelf.html). * [`logstash`](https://github.com/bshuster-repo/logrus-logstash-hook). Logs fields as [Logstash](http://logstash.net) Events. * [`prefixed`](https://github.com/x-cray/logrus-prefixed-formatter). Displays log entry source along with alternative layout. * [`zalgo`](https://github.com/aybabtme/logzalgo). Invoking the P͉̫o̳̼̊w̖͈̰͎e̬͔̭͂r͚̼̹̲ ̫͓͉̳͈ō̠͕͖̚f̝͍̠ ͕̲̞͖͑Z̖̫̤̫ͪa͉̬͈̗l͖͎g̳̥o̰̥̅!̣͔̲̻͊̄ ̙̘̦̹̦. diff --git a/alt_exit_test.go b/alt_exit_test.go index a08b1a8..0a2ff56 100644 --- a/alt_exit_test.go +++ b/alt_exit_test.go @@ -6,6 +6,8 @@ import ( "os" "os/exec" "path/filepath" + "runtime" + "strings" "testing" "time" ) @@ -19,6 +21,9 @@ func TestRegister(t *testing.T) { } func TestHandler(t *testing.T) { + testprog := testprogleader + testprog = append(testprog, getPackage()...) + testprog = append(testprog, testprogtrailer...) tempDir, err := ioutil.TempDir("", "test_handler") if err != nil { log.Fatalf("can't create temp dir. %q", err) @@ -47,13 +52,24 @@ func TestHandler(t *testing.T) { } } -var testprog = []byte(` +// getPackage returns the name of the current package, which makes running this +// test in a fork simpler +func getPackage() []byte { + pc, _, _, _ := runtime.Caller(0) + fullFuncName := runtime.FuncForPC(pc).Name() + idx := strings.LastIndex(fullFuncName, ".") + return []byte(fullFuncName[:idx]) // trim off function details +} + +var testprogleader = []byte(` // Test program for atexit, gets output file and data as arguments and writes // data to output file in atexit handler. package main import ( - "github.com/sirupsen/logrus" + "`) +var testprogtrailer = []byte( + `" "flag" "fmt" "io/ioutil" diff --git a/entry.go b/entry.go index d075d72..cc85d3a 100644 --- a/entry.go +++ b/entry.go @@ -4,11 +4,30 @@ import ( "bytes" "fmt" "os" + "reflect" + "runtime" + "strings" "sync" "time" ) -var bufferPool *sync.Pool +var ( + bufferPool *sync.Pool + + // qualified package name, cached at first use + logrusPackage string + + // Positions in the call stack when tracing to report the calling method + minimumCallerDepth int + + // Used for caller information initialisation + callerInitOnce sync.Once +) + +const ( + maximumCallerDepth int = 25 + knownLogrusFrames int = 4 +) func init() { bufferPool = &sync.Pool{ @@ -16,15 +35,18 @@ func init() { return new(bytes.Buffer) }, } + + // start at the bottom of the stack before the package-name cache is primed + minimumCallerDepth = 1 } // Defines the key when adding errors using WithError. var ErrorKey = "error" // An entry is the final or intermediate Logrus logging entry. It contains all -// the fields passed with WithField{,s}. It's finally logged when Debug, Info, -// Warn, Error, Fatal or Panic is called on it. These objects can be reused and -// passed around as much as you wish to avoid field duplication. +// the fields passed with WithField{,s}. It's finally logged when Trace, Debug, +// Info, Warn, Error, Fatal or Panic is called on it. These objects can be +// reused and passed around as much as you wish to avoid field duplication. type Entry struct { Logger *Logger @@ -34,22 +56,28 @@ type Entry struct { // Time at which the log entry was created Time time.Time - // Level the log entry was logged at: Debug, Info, Warn, Error, Fatal or Panic + // Level the log entry was logged at: Trace, Debug, Info, Warn, Error, Fatal or Panic // This field will be set on entry firing and the value will be equal to the one in Logger struct field. Level Level - // Message passed to Debug, Info, Warn, Error, Fatal or Panic + // Calling method, with package name + Caller *runtime.Frame + + // Message passed to Trace, Debug, Info, Warn, Error, Fatal or Panic Message string - // When formatter is called in entry.log(), an Buffer may be set to entry + // When formatter is called in entry.log(), a Buffer may be set to entry Buffer *bytes.Buffer + + // err may contain a field formatting error + err string } func NewEntry(logger *Logger) *Entry { return &Entry{ Logger: logger, - // Default is five fields, give a little extra room - Data: make(Fields, 5), + // Default is three fields, plus one optional. Give a little extra room. + Data: make(Fields, 6), } } @@ -80,19 +108,95 @@ func (entry *Entry) WithFields(fields Fields) *Entry { for k, v := range entry.Data { data[k] = v } + var field_err string for k, v := range fields { - data[k] = v + if t := reflect.TypeOf(v); t != nil && t.Kind() == reflect.Func { + field_err = fmt.Sprintf("can not add field %q", k) + if entry.err != "" { + field_err = entry.err + ", " + field_err + } + } else { + data[k] = v + } } - return &Entry{Logger: entry.Logger, Data: data} + return &Entry{Logger: entry.Logger, Data: data, Time: entry.Time, err: field_err} +} + +// Overrides the time of the Entry. +func (entry *Entry) WithTime(t time.Time) *Entry { + return &Entry{Logger: entry.Logger, Data: entry.Data, Time: t} +} + +// getPackageName reduces a fully qualified function name to the package name +// There really ought to be to be a better way... +func getPackageName(f string) string { + for { + lastPeriod := strings.LastIndex(f, ".") + lastSlash := strings.LastIndex(f, "/") + if lastPeriod > lastSlash { + f = f[:lastPeriod] + } else { + break + } + } + + return f +} + +// getCaller retrieves the name of the first non-logrus calling function +func getCaller() *runtime.Frame { + // Restrict the lookback frames to avoid runaway lookups + pcs := make([]uintptr, maximumCallerDepth) + depth := runtime.Callers(minimumCallerDepth, pcs) + frames := runtime.CallersFrames(pcs[:depth]) + + // cache this package's fully-qualified name + callerInitOnce.Do(func() { + logrusPackage = getPackageName(runtime.FuncForPC(pcs[0]).Name()) + + // now that we have the cache, we can skip a minimum count of known-logrus functions + // XXX this is dubious, the number of frames may vary store an entry in a logger interface + minimumCallerDepth = knownLogrusFrames + }) + + for f, again := frames.Next(); again; f, again = frames.Next() { + pkg := getPackageName(f.Function) + + // If the caller isn't part of this package, we're done + if pkg != logrusPackage { + return &f + } + } + + // if we got here, we failed to find the caller's context + return nil +} + +func (entry Entry) HasCaller() (has bool) { + return entry.Logger != nil && + entry.Logger.ReportCaller && + entry.Caller != nil } // 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 + if entry.Logger.ReportCaller { + entry.Caller = getCaller() + } entry.fireHooks() @@ -113,21 +217,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 { @@ -138,8 +240,14 @@ func (entry *Entry) write() { } } +func (entry *Entry) Trace(args ...interface{}) { + if entry.Logger.IsLevelEnabled(TraceLevel) { + entry.log(TraceLevel, fmt.Sprint(args...)) + } +} + func (entry *Entry) Debug(args ...interface{}) { - if entry.Logger.level() >= DebugLevel { + if entry.Logger.IsLevelEnabled(DebugLevel) { entry.log(DebugLevel, fmt.Sprint(args...)) } } @@ -149,13 +257,13 @@ func (entry *Entry) Print(args ...interface{}) { } func (entry *Entry) Info(args ...interface{}) { - if entry.Logger.level() >= InfoLevel { + if entry.Logger.IsLevelEnabled(InfoLevel) { entry.log(InfoLevel, fmt.Sprint(args...)) } } func (entry *Entry) Warn(args ...interface{}) { - if entry.Logger.level() >= WarnLevel { + if entry.Logger.IsLevelEnabled(WarnLevel) { entry.log(WarnLevel, fmt.Sprint(args...)) } } @@ -165,20 +273,20 @@ func (entry *Entry) Warning(args ...interface{}) { } func (entry *Entry) Error(args ...interface{}) { - if entry.Logger.level() >= ErrorLevel { + if entry.Logger.IsLevelEnabled(ErrorLevel) { entry.log(ErrorLevel, fmt.Sprint(args...)) } } func (entry *Entry) Fatal(args ...interface{}) { - if entry.Logger.level() >= FatalLevel { + if entry.Logger.IsLevelEnabled(FatalLevel) { entry.log(FatalLevel, fmt.Sprint(args...)) } - Exit(1) + entry.Logger.Exit(1) } func (entry *Entry) Panic(args ...interface{}) { - if entry.Logger.level() >= PanicLevel { + if entry.Logger.IsLevelEnabled(PanicLevel) { entry.log(PanicLevel, fmt.Sprint(args...)) } panic(fmt.Sprint(args...)) @@ -186,14 +294,20 @@ func (entry *Entry) Panic(args ...interface{}) { // Entry Printf family functions +func (entry *Entry) Tracef(format string, args ...interface{}) { + if entry.Logger.IsLevelEnabled(TraceLevel) { + entry.Trace(fmt.Sprintf(format, args...)) + } +} + func (entry *Entry) Debugf(format string, args ...interface{}) { - if entry.Logger.level() >= DebugLevel { + if entry.Logger.IsLevelEnabled(DebugLevel) { entry.Debug(fmt.Sprintf(format, args...)) } } func (entry *Entry) Infof(format string, args ...interface{}) { - if entry.Logger.level() >= InfoLevel { + if entry.Logger.IsLevelEnabled(InfoLevel) { entry.Info(fmt.Sprintf(format, args...)) } } @@ -203,7 +317,7 @@ func (entry *Entry) Printf(format string, args ...interface{}) { } func (entry *Entry) Warnf(format string, args ...interface{}) { - if entry.Logger.level() >= WarnLevel { + if entry.Logger.IsLevelEnabled(WarnLevel) { entry.Warn(fmt.Sprintf(format, args...)) } } @@ -213,34 +327,40 @@ func (entry *Entry) Warningf(format string, args ...interface{}) { } func (entry *Entry) Errorf(format string, args ...interface{}) { - if entry.Logger.level() >= ErrorLevel { + if entry.Logger.IsLevelEnabled(ErrorLevel) { entry.Error(fmt.Sprintf(format, args...)) } } func (entry *Entry) Fatalf(format string, args ...interface{}) { - if entry.Logger.level() >= FatalLevel { + if entry.Logger.IsLevelEnabled(FatalLevel) { entry.Fatal(fmt.Sprintf(format, args...)) } - Exit(1) + entry.Logger.Exit(1) } func (entry *Entry) Panicf(format string, args ...interface{}) { - if entry.Logger.level() >= PanicLevel { + if entry.Logger.IsLevelEnabled(PanicLevel) { entry.Panic(fmt.Sprintf(format, args...)) } } // Entry Println family functions +func (entry *Entry) Traceln(args ...interface{}) { + if entry.Logger.IsLevelEnabled(TraceLevel) { + entry.Trace(entry.sprintlnn(args...)) + } +} + func (entry *Entry) Debugln(args ...interface{}) { - if entry.Logger.level() >= DebugLevel { + if entry.Logger.IsLevelEnabled(DebugLevel) { entry.Debug(entry.sprintlnn(args...)) } } func (entry *Entry) Infoln(args ...interface{}) { - if entry.Logger.level() >= InfoLevel { + if entry.Logger.IsLevelEnabled(InfoLevel) { entry.Info(entry.sprintlnn(args...)) } } @@ -250,7 +370,7 @@ func (entry *Entry) Println(args ...interface{}) { } func (entry *Entry) Warnln(args ...interface{}) { - if entry.Logger.level() >= WarnLevel { + if entry.Logger.IsLevelEnabled(WarnLevel) { entry.Warn(entry.sprintlnn(args...)) } } @@ -260,20 +380,20 @@ func (entry *Entry) Warningln(args ...interface{}) { } func (entry *Entry) Errorln(args ...interface{}) { - if entry.Logger.level() >= ErrorLevel { + if entry.Logger.IsLevelEnabled(ErrorLevel) { entry.Error(entry.sprintlnn(args...)) } } func (entry *Entry) Fatalln(args ...interface{}) { - if entry.Logger.level() >= FatalLevel { + if entry.Logger.IsLevelEnabled(FatalLevel) { entry.Fatal(entry.sprintlnn(args...)) } - Exit(1) + entry.Logger.Exit(1) } func (entry *Entry) Panicln(args ...interface{}) { - if entry.Logger.level() >= PanicLevel { + if entry.Logger.IsLevelEnabled(PanicLevel) { entry.Panic(entry.sprintlnn(args...)) } } diff --git a/example_basic_test.go b/example_basic_test.go index a2acf55..9ff5655 100644 --- a/example_basic_test.go +++ b/example_basic_test.go @@ -1,16 +1,18 @@ package logrus_test import ( - "github.com/sirupsen/logrus" "os" + + "github.com/sirupsen/logrus" ) func Example_basic() { var log = logrus.New() log.Formatter = new(logrus.JSONFormatter) log.Formatter = new(logrus.TextFormatter) //default + log.Formatter.(*logrus.TextFormatter).DisableColors = true // remove colors log.Formatter.(*logrus.TextFormatter).DisableTimestamp = true // remove timestamp from test output - log.Level = logrus.DebugLevel + log.Level = logrus.TraceLevel log.Out = os.Stdout // file, err := os.OpenFile("logrus.log", os.O_CREATE|os.O_WRONLY, 0666) @@ -35,6 +37,11 @@ func Example_basic() { } }() + log.WithFields(logrus.Fields{ + "animal": "walrus", + "number": 0, + }).Trace("Went to the beach") + log.WithFields(logrus.Fields{ "animal": "walrus", "number": 8, @@ -60,6 +67,7 @@ func Example_basic() { }).Panic("It's over 9000!") // Output: + // level=trace msg="Went to the beach" animal=walrus number=0 // level=debug msg="Started observing beach" animal=walrus number=8 // level=info msg="A group of walrus emerges from the ocean" animal=walrus size=10 // level=warning msg="The group's number increased tremendously!" number=122 omg=true diff --git a/example_global_hook_test.go b/example_global_hook_test.go new file mode 100644 index 0000000..c81e448 --- /dev/null +++ b/example_global_hook_test.go @@ -0,0 +1,36 @@ +package logrus_test + +import ( + "github.com/sirupsen/logrus" + "os" +) + +var ( + mystring string +) + +type GlobalHook struct { +} + +func (h *GlobalHook) Levels() []logrus.Level { + return logrus.AllLevels +} + +func (h *GlobalHook) Fire(e *logrus.Entry) error { + e.Data["mystring"] = mystring + return nil +} + +func Example() { + l := logrus.New() + l.Out = os.Stdout + l.Formatter = &logrus.TextFormatter{DisableTimestamp: true, DisableColors: true} + l.AddHook(&GlobalHook{}) + mystring = "first value" + l.Info("first log") + mystring = "another value" + l.Info("second log") + // Output: + // level=info msg="first log" mystring="first value" + // level=info msg="second log" mystring="another value" +} diff --git a/example_hook_test.go b/example_hook_test.go index d4ddffc..15118d2 100644 --- a/example_hook_test.go +++ b/example_hook_test.go @@ -1,16 +1,24 @@ +// +build !windows + package logrus_test import ( - "github.com/sirupsen/logrus" - "gopkg.in/gemnasium/logrus-airbrake-hook.v2" + "log/syslog" "os" + + "github.com/sirupsen/logrus" + slhooks "github.com/sirupsen/logrus/hooks/syslog" ) +// An example on how to use a hook func Example_hook() { var log = logrus.New() log.Formatter = new(logrus.TextFormatter) // default + log.Formatter.(*logrus.TextFormatter).DisableColors = true // remove colors log.Formatter.(*logrus.TextFormatter).DisableTimestamp = true // remove timestamp from test output - log.Hooks.Add(airbrake.NewHook(123, "xyz", "development")) + if sl, err := slhooks.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, ""); err != nil { + log.Hooks.Add(sl) + } log.Out = os.Stdout log.WithFields(logrus.Fields{ diff --git a/exported.go b/exported.go index c99e243..7342613 100644 --- a/exported.go +++ b/exported.go @@ -2,6 +2,7 @@ package logrus import ( "io" + "time" ) var ( @@ -20,30 +21,33 @@ func SetOutput(out io.Writer) { // SetFormatter sets the standard logger formatter. func SetFormatter(formatter Formatter) { - std.mu.Lock() - defer std.mu.Unlock() - std.Formatter = formatter + std.SetFormatter(formatter) +} + +// SetReportCaller sets whether the standard logger will include the calling +// method as a field. +func SetReportCaller(include bool) { + std.SetReportCaller(include) } // 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() +} + +// IsLevelEnabled checks if the log level of the standard logger is greater than the level param +func IsLevelEnabled(level Level) bool { + return std.IsLevelEnabled(level) } // 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. @@ -70,6 +74,20 @@ 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) +} + +// Trace logs a message at level Trace on the standard logger. +func Trace(args ...interface{}) { + std.Trace(args...) +} + // Debug logs a message at level Debug on the standard logger. func Debug(args ...interface{}) { std.Debug(args...) @@ -110,6 +128,11 @@ func Fatal(args ...interface{}) { std.Fatal(args...) } +// Tracef logs a message at level Trace on the standard logger. +func Tracef(format string, args ...interface{}) { + std.Tracef(format, args...) +} + // Debugf logs a message at level Debug on the standard logger. func Debugf(format string, args ...interface{}) { std.Debugf(format, args...) @@ -150,6 +173,11 @@ func Fatalf(format string, args ...interface{}) { std.Fatalf(format, args...) } +// Traceln logs a message at level Trace on the standard logger. +func Traceln(args ...interface{}) { + std.Traceln(args...) +} + // Debugln logs a message at level Debug on the standard logger. func Debugln(args ...interface{}) { std.Debugln(args...) diff --git a/formatter.go b/formatter.go index 83c7494..4088837 100644 --- a/formatter.go +++ b/formatter.go @@ -2,7 +2,16 @@ package logrus import "time" -const defaultTimestampFormat = time.RFC3339 +// Default key names for the default fields +const ( + defaultTimestampFormat = time.RFC3339 + FieldKeyMsg = "msg" + FieldKeyLevel = "level" + FieldKeyTime = "time" + FieldKeyLogrusError = "logrus_error" + FieldKeyFunc = "func" + FieldKeyFile = "file" +) // The Formatter interface is used to implement a custom Formatter. It takes an // `Entry`. It exposes all the fields, including the default ones: @@ -18,7 +27,7 @@ type Formatter interface { Format(*Entry) ([]byte, error) } -// This is to not silently overwrite `time`, `msg` and `level` fields when +// This is to not silently overwrite `time`, `msg`, `func` and `level` fields when // dumping it. If this code wasn't there doing: // // logrus.WithField("level", 1).Info("hello") @@ -30,7 +39,7 @@ type Formatter interface { // // It's not exported because it's still using Data in an opinionated way. It's to // avoid code duplication between the two default formatters. -func prefixFieldClashes(data Fields, fieldMap FieldMap) { +func prefixFieldClashes(data Fields, fieldMap FieldMap, reportCaller bool) { timeKey := fieldMap.resolve(FieldKeyTime) if t, ok := data[timeKey]; ok { data["fields."+timeKey] = t @@ -48,4 +57,22 @@ func prefixFieldClashes(data Fields, fieldMap FieldMap) { data["fields."+levelKey] = l delete(data, levelKey) } + + logrusErrKey := fieldMap.resolve(FieldKeyLogrusError) + if l, ok := data[logrusErrKey]; ok { + data["fields."+logrusErrKey] = l + delete(data, logrusErrKey) + } + + // If reportCaller is not set, 'func' will not conflict. + if reportCaller { + funcKey := fieldMap.resolve(FieldKeyFunc) + if l, ok := data[funcKey]; ok { + data["fields."+funcKey] = l + } + fileKey := fieldMap.resolve(FieldKeyFile) + if l, ok := data[fileKey]; ok { + data["fields."+fileKey] = l + } + } } diff --git a/go.mod b/go.mod new file mode 100644 index 0000000..94574cc --- /dev/null +++ b/go.mod @@ -0,0 +1,11 @@ +module github.com/sirupsen/logrus + +require ( + github.com/davecgh/go-spew v1.1.1 // indirect + github.com/konsorten/go-windows-terminal-sequences v1.0.1 + github.com/pmezard/go-difflib v1.0.0 // indirect + github.com/stretchr/objx v0.1.1 // indirect + github.com/stretchr/testify v1.2.2 + golang.org/x/crypto v0.0.0-20180904163835-0709b304e793 + golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33 +) diff --git a/go.sum b/go.sum new file mode 100644 index 0000000..133d34a --- /dev/null +++ b/go.sum @@ -0,0 +1,15 @@ +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/konsorten/go-windows-terminal-sequences v0.0.0-20180402223658-b729f2633dfe h1:CHRGQ8V7OlCYtwaKPJi3iA7J+YdNKdo8j7nG5IgDhjs= +github.com/konsorten/go-windows-terminal-sequences v0.0.0-20180402223658-b729f2633dfe/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ= +github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/stretchr/objx v0.1.1 h1:2vfRuCMp5sSVIDSqO8oNnWJq7mPa6KVP3iPIwFBuy8A= +github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w= +github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= +golang.org/x/crypto v0.0.0-20180904163835-0709b304e793 h1:u+LnwYTOOW7Ukr/fppxEb1Nwz0AtPflrblfvUudpo+I= +golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4= +golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33 h1:I6FyU15t786LL7oL/hn43zqTuEGr4PN7F4XJ1p4E3Y8= +golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= diff --git a/hook_test.go b/hook_test.go index 4fea751..b967593 100644 --- a/hook_test.go +++ b/hook_test.go @@ -1,10 +1,16 @@ -package logrus +package logrus_test import ( + "bytes" + "encoding/json" "sync" "testing" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + . "github.com/sirupsen/logrus" + . "github.com/sirupsen/logrus/internal/testutils" ) type TestHook struct { @@ -18,6 +24,7 @@ func (hook *TestHook) Fire(entry *Entry) error { func (hook *TestHook) Levels() []Level { return []Level{ + TraceLevel, DebugLevel, InfoLevel, WarnLevel, @@ -50,6 +57,7 @@ func (hook *ModifyHook) Fire(entry *Entry) error { func (hook *ModifyHook) Levels() []Level { return []Level{ + TraceLevel, DebugLevel, InfoLevel, WarnLevel, @@ -85,6 +93,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/syslog/syslog.go b/hooks/syslog/syslog.go index 329ce0d..02b8df3 100644 --- a/hooks/syslog/syslog.go +++ b/hooks/syslog/syslog.go @@ -43,7 +43,7 @@ func (hook *SyslogHook) Fire(entry *logrus.Entry) error { return hook.Writer.Warning(line) case logrus.InfoLevel: return hook.Writer.Info(line) - case logrus.DebugLevel: + case logrus.DebugLevel, logrus.TraceLevel: return hook.Writer.Debug(line) default: return nil diff --git a/hooks/syslog/syslog_test.go b/hooks/syslog/syslog_test.go index 5ec3a44..bec6efd 100644 --- a/hooks/syslog/syslog_test.go +++ b/hooks/syslog/syslog_test.go @@ -1,3 +1,5 @@ +// +build !windows,!nacl,!plan9 + package syslog import ( 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..636bad5 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,46 @@ 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)) } + +func TestFatalWithAlternateExit(t *testing.T) { + assert := assert.New(t) + + logger, hook := NewNullLogger() + logger.ExitFunc = func(code int) {} + + logger.Fatal("something went very wrong") + assert.Equal(logrus.FatalLevel, hook.LastEntry().Level) + assert.Equal("something went very wrong", hook.LastEntry().Message) + assert.Equal(1, len(hook.Entries)) +} diff --git a/internal/testutils/testutils.go b/internal/testutils/testutils.go new file mode 100644 index 0000000..20bc3c3 --- /dev/null +++ b/internal/testutils/testutils.go @@ -0,0 +1,58 @@ +package testutils + +import ( + "bytes" + "encoding/json" + "strconv" + "strings" + "testing" + + . "github.com/sirupsen/logrus" + + "github.com/stretchr/testify/require" +) + +func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) { + var buffer bytes.Buffer + var fields Fields + + logger := New() + logger.Out = &buffer + logger.Formatter = new(JSONFormatter) + + log(logger) + + err := json.Unmarshal(buffer.Bytes(), &fields) + require.Nil(t, err) + + 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 := kvArr[1] + if kvArr[1][0] == '"' { + var err error + val, err = strconv.Unquote(val) + require.NoError(t, err) + } + fields[key] = val + } + assertions(fields) +} diff --git a/json_formatter.go b/json_formatter.go index dab1761..2605753 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -1,6 +1,7 @@ package logrus import ( + "bytes" "encoding/json" "fmt" ) @@ -10,13 +11,6 @@ type fieldKey string // FieldMap allows customization of the key names for default fields. type FieldMap map[fieldKey]string -// Default key names for the default fields -const ( - FieldKeyMsg = "msg" - FieldKeyLevel = "level" - FieldKeyTime = "time" -) - func (f FieldMap) resolve(key fieldKey) string { if k, ok := f[key]; ok { return k @@ -40,17 +34,21 @@ type JSONFormatter struct { // As an example: // formatter := &JSONFormatter{ // FieldMap: FieldMap{ - // FieldKeyTime: "@timestamp", + // FieldKeyTime: "@timestamp", // FieldKeyLevel: "@level", - // FieldKeyMsg: "@message", + // FieldKeyMsg: "@message", + // FieldKeyFunc: "@caller", // }, // } FieldMap FieldMap + + // PrettyPrint will indent all json logs + PrettyPrint bool } // Format renders a single log entry func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { - data := make(Fields, len(entry.Data)+3) + data := make(Fields, len(entry.Data)+4) for k, v := range entry.Data { switch v := v.(type) { case error: @@ -68,22 +66,40 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data = newData } - prefixFieldClashes(data, f.FieldMap) + prefixFieldClashes(data, f.FieldMap, entry.HasCaller()) timestampFormat := f.TimestampFormat if timestampFormat == "" { timestampFormat = defaultTimestampFormat } + if entry.err != "" { + data[f.FieldMap.resolve(FieldKeyLogrusError)] = entry.err + } if !f.DisableTimestamp { data[f.FieldMap.resolve(FieldKeyTime)] = entry.Time.Format(timestampFormat) } data[f.FieldMap.resolve(FieldKeyMsg)] = entry.Message data[f.FieldMap.resolve(FieldKeyLevel)] = entry.Level.String() + if entry.HasCaller() { + data[f.FieldMap.resolve(FieldKeyFunc)] = entry.Caller.Function + data[f.FieldMap.resolve(FieldKeyFile)] = fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + } - serialized, err := json.Marshal(data) - if err != nil { + var b *bytes.Buffer + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } + + encoder := json.NewEncoder(b) + if f.PrettyPrint { + encoder.SetIndent("", " ") + } + if err := encoder.Encode(data); 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 0dde300..695c36e 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -4,6 +4,7 @@ import ( "encoding/json" "errors" "fmt" + "runtime" "strings" "testing" ) @@ -167,8 +168,8 @@ func TestFieldsInNestedDictionary(t *testing.T) { } logEntry := WithFields(Fields{ - "level": "level", - "test": "test", + "level": "level", + "test": "test", }) logEntry.Level = InfoLevel @@ -267,6 +268,55 @@ func TestJSONTimeKey(t *testing.T) { } } +func TestFieldDoesNotClashWithCaller(t *testing.T) { + SetReportCaller(false) + formatter := &JSONFormatter{} + + b, err := formatter.Format(WithField("func", "howdy pardner")) + 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) + } + + if entry["func"] != "howdy pardner" { + t.Fatal("func field replaced when ReportCaller=false") + } +} + +func TestFieldClashWithCaller(t *testing.T) { + SetReportCaller(true) + formatter := &JSONFormatter{} + e := WithField("func", "howdy pardner") + e.Caller = &runtime.Frame{Function: "somefunc"} + b, err := formatter.Format(e) + 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) + } + + if entry["fields.func"] != "howdy pardner" { + t.Fatalf("fields.func not set to original func field when ReportCaller=true (got '%s')", + entry["fields.func"]) + } + + if entry["func"] != "somefunc" { + t.Fatalf("func not set as expected when ReportCaller=true (got '%s')", + entry["func"]) + } + + SetReportCaller(false) // return to default value +} + func TestJSONDisableTimestamp(t *testing.T) { formatter := &JSONFormatter{ DisableTimestamp: true, diff --git a/logger.go b/logger.go index eab53d1..6ce9a9d 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 @@ -23,6 +24,10 @@ type Logger struct { // own that implements the `Formatter` interface, see the `README` or included // formatters for examples. Formatter Formatter + + // Flag for whether to log caller info (off by default) + ReportCaller bool + // The logging level the logger should log at. This is typically (and defaults // to) `logrus.Info`, which allows Info(), Warn(), Error() and Fatal() to be // logged. @@ -31,8 +36,12 @@ type Logger struct { mu MutexWrap // Reusable empty entry entryPool sync.Pool + // Function to exit the application, defaults to `os.Exit()` + ExitFunc exitFunc } +type exitFunc func(int) + type MutexWrap struct { lock sync.Mutex disabled bool @@ -68,10 +77,12 @@ func (mw *MutexWrap) Disable() { // It's recommended to make this a global instance called `log`. func New() *Logger { return &Logger{ - Out: os.Stderr, - Formatter: new(TextFormatter), - Hooks: make(LevelHooks), - Level: InfoLevel, + Out: os.Stderr, + Formatter: new(TextFormatter), + Hooks: make(LevelHooks), + Level: InfoLevel, + ExitFunc: os.Exit, + ReportCaller: false, } } @@ -84,6 +95,7 @@ func (logger *Logger) newEntry() *Entry { } func (logger *Logger) releaseEntry(entry *Entry) { + entry.Data = map[string]interface{}{} logger.entryPool.Put(entry) } @@ -112,8 +124,23 @@ 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) Tracef(format string, args ...interface{}) { + if logger.IsLevelEnabled(TraceLevel) { + entry := logger.newEntry() + entry.Tracef(format, args...) + logger.releaseEntry(entry) + } +} + func (logger *Logger) Debugf(format string, args ...interface{}) { - if logger.level() >= DebugLevel { + if logger.IsLevelEnabled(DebugLevel) { entry := logger.newEntry() entry.Debugf(format, args...) logger.releaseEntry(entry) @@ -121,7 +148,7 @@ func (logger *Logger) Debugf(format string, args ...interface{}) { } func (logger *Logger) Infof(format string, args ...interface{}) { - if logger.level() >= InfoLevel { + if logger.IsLevelEnabled(InfoLevel) { entry := logger.newEntry() entry.Infof(format, args...) logger.releaseEntry(entry) @@ -135,7 +162,7 @@ func (logger *Logger) Printf(format string, args ...interface{}) { } func (logger *Logger) Warnf(format string, args ...interface{}) { - if logger.level() >= WarnLevel { + if logger.IsLevelEnabled(WarnLevel) { entry := logger.newEntry() entry.Warnf(format, args...) logger.releaseEntry(entry) @@ -143,7 +170,7 @@ func (logger *Logger) Warnf(format string, args ...interface{}) { } func (logger *Logger) Warningf(format string, args ...interface{}) { - if logger.level() >= WarnLevel { + if logger.IsLevelEnabled(WarnLevel) { entry := logger.newEntry() entry.Warnf(format, args...) logger.releaseEntry(entry) @@ -151,7 +178,7 @@ func (logger *Logger) Warningf(format string, args ...interface{}) { } func (logger *Logger) Errorf(format string, args ...interface{}) { - if logger.level() >= ErrorLevel { + if logger.IsLevelEnabled(ErrorLevel) { entry := logger.newEntry() entry.Errorf(format, args...) logger.releaseEntry(entry) @@ -159,24 +186,32 @@ func (logger *Logger) Errorf(format string, args ...interface{}) { } func (logger *Logger) Fatalf(format string, args ...interface{}) { - if logger.level() >= FatalLevel { + if logger.IsLevelEnabled(FatalLevel) { entry := logger.newEntry() entry.Fatalf(format, args...) logger.releaseEntry(entry) } - Exit(1) + logger.Exit(1) } func (logger *Logger) Panicf(format string, args ...interface{}) { - if logger.level() >= PanicLevel { + if logger.IsLevelEnabled(PanicLevel) { entry := logger.newEntry() entry.Panicf(format, args...) logger.releaseEntry(entry) } } +func (logger *Logger) Trace(args ...interface{}) { + if logger.IsLevelEnabled(TraceLevel) { + entry := logger.newEntry() + entry.Trace(args...) + logger.releaseEntry(entry) + } +} + func (logger *Logger) Debug(args ...interface{}) { - if logger.level() >= DebugLevel { + if logger.IsLevelEnabled(DebugLevel) { entry := logger.newEntry() entry.Debug(args...) logger.releaseEntry(entry) @@ -184,7 +219,7 @@ func (logger *Logger) Debug(args ...interface{}) { } func (logger *Logger) Info(args ...interface{}) { - if logger.level() >= InfoLevel { + if logger.IsLevelEnabled(InfoLevel) { entry := logger.newEntry() entry.Info(args...) logger.releaseEntry(entry) @@ -198,7 +233,7 @@ func (logger *Logger) Print(args ...interface{}) { } func (logger *Logger) Warn(args ...interface{}) { - if logger.level() >= WarnLevel { + if logger.IsLevelEnabled(WarnLevel) { entry := logger.newEntry() entry.Warn(args...) logger.releaseEntry(entry) @@ -206,7 +241,7 @@ func (logger *Logger) Warn(args ...interface{}) { } func (logger *Logger) Warning(args ...interface{}) { - if logger.level() >= WarnLevel { + if logger.IsLevelEnabled(WarnLevel) { entry := logger.newEntry() entry.Warn(args...) logger.releaseEntry(entry) @@ -214,7 +249,7 @@ func (logger *Logger) Warning(args ...interface{}) { } func (logger *Logger) Error(args ...interface{}) { - if logger.level() >= ErrorLevel { + if logger.IsLevelEnabled(ErrorLevel) { entry := logger.newEntry() entry.Error(args...) logger.releaseEntry(entry) @@ -222,24 +257,32 @@ func (logger *Logger) Error(args ...interface{}) { } func (logger *Logger) Fatal(args ...interface{}) { - if logger.level() >= FatalLevel { + if logger.IsLevelEnabled(FatalLevel) { entry := logger.newEntry() entry.Fatal(args...) logger.releaseEntry(entry) } - Exit(1) + logger.Exit(1) } func (logger *Logger) Panic(args ...interface{}) { - if logger.level() >= PanicLevel { + if logger.IsLevelEnabled(PanicLevel) { entry := logger.newEntry() entry.Panic(args...) logger.releaseEntry(entry) } } +func (logger *Logger) Traceln(args ...interface{}) { + if logger.IsLevelEnabled(TraceLevel) { + entry := logger.newEntry() + entry.Traceln(args...) + logger.releaseEntry(entry) + } +} + func (logger *Logger) Debugln(args ...interface{}) { - if logger.level() >= DebugLevel { + if logger.IsLevelEnabled(DebugLevel) { entry := logger.newEntry() entry.Debugln(args...) logger.releaseEntry(entry) @@ -247,7 +290,7 @@ func (logger *Logger) Debugln(args ...interface{}) { } func (logger *Logger) Infoln(args ...interface{}) { - if logger.level() >= InfoLevel { + if logger.IsLevelEnabled(InfoLevel) { entry := logger.newEntry() entry.Infoln(args...) logger.releaseEntry(entry) @@ -261,7 +304,7 @@ func (logger *Logger) Println(args ...interface{}) { } func (logger *Logger) Warnln(args ...interface{}) { - if logger.level() >= WarnLevel { + if logger.IsLevelEnabled(WarnLevel) { entry := logger.newEntry() entry.Warnln(args...) logger.releaseEntry(entry) @@ -269,7 +312,7 @@ func (logger *Logger) Warnln(args ...interface{}) { } func (logger *Logger) Warningln(args ...interface{}) { - if logger.level() >= WarnLevel { + if logger.IsLevelEnabled(WarnLevel) { entry := logger.newEntry() entry.Warnln(args...) logger.releaseEntry(entry) @@ -277,7 +320,7 @@ func (logger *Logger) Warningln(args ...interface{}) { } func (logger *Logger) Errorln(args ...interface{}) { - if logger.level() >= ErrorLevel { + if logger.IsLevelEnabled(ErrorLevel) { entry := logger.newEntry() entry.Errorln(args...) logger.releaseEntry(entry) @@ -285,22 +328,30 @@ func (logger *Logger) Errorln(args ...interface{}) { } func (logger *Logger) Fatalln(args ...interface{}) { - if logger.level() >= FatalLevel { + if logger.IsLevelEnabled(FatalLevel) { entry := logger.newEntry() entry.Fatalln(args...) logger.releaseEntry(entry) } - Exit(1) + logger.Exit(1) } func (logger *Logger) Panicln(args ...interface{}) { - if logger.level() >= PanicLevel { + if logger.IsLevelEnabled(PanicLevel) { entry := logger.newEntry() entry.Panicln(args...) logger.releaseEntry(entry) } } +func (logger *Logger) Exit(code int) { + runHandlers() + if logger.ExitFunc == nil { + logger.ExitFunc = os.Exit + } + logger.ExitFunc(code) +} + //When file is opened with appending mode, it's safe to //write concurrently to a file (within 4k message on Linux). //In these cases user can choose to disable the lock. @@ -312,6 +363,7 @@ 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)) } @@ -331,8 +383,48 @@ func (logger *Logger) SetOutput(out io.Writer) { logger.Out = out } +// 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() logger.Hooks.Add(hook) } + +// IsLevelEnabled checks if the log level of the logger is greater than the level param +func (logger *Logger) IsLevelEnabled(level Level) bool { + return logger.level() >= level +} + +// 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 +} + +func (logger *Logger) SetReportCaller(reportCaller bool) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.ReportCaller = reportCaller +} + +// 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/logger_test.go b/logger_test.go new file mode 100644 index 0000000..73ba450 --- /dev/null +++ b/logger_test.go @@ -0,0 +1,42 @@ +package logrus + +import ( + "bytes" + "encoding/json" + "fmt" + "testing" + + "github.com/stretchr/testify/require" +) + +func TestFieldValueError(t *testing.T) { + buf := &bytes.Buffer{} + l := &Logger{ + Out: buf, + Formatter: new(JSONFormatter), + Hooks: make(LevelHooks), + Level: DebugLevel, + } + l.WithField("func", func() {}).Info("test") + fmt.Println(buf.String()) + var data map[string]interface{} + json.Unmarshal(buf.Bytes(), &data) + _, ok := data[FieldKeyLogrusError] + require.True(t, ok) +} + +func TestNoFieldValueError(t *testing.T) { + buf := &bytes.Buffer{} + l := &Logger{ + Out: buf, + Formatter: new(JSONFormatter), + Hooks: make(LevelHooks), + Level: DebugLevel, + } + l.WithField("str", "str").Info("test") + fmt.Println(buf.String()) + var data map[string]interface{} + json.Unmarshal(buf.Bytes(), &data) + _, ok := data[FieldKeyLogrusError] + require.False(t, ok) +} diff --git a/logrus.go b/logrus.go index dd38999..4ef4518 100644 --- a/logrus.go +++ b/logrus.go @@ -15,6 +15,8 @@ type Level uint32 // Convert the Level to a string. E.g. PanicLevel becomes "panic". func (level Level) String() string { switch level { + case TraceLevel: + return "trace" case DebugLevel: return "debug" case InfoLevel: @@ -47,12 +49,26 @@ func ParseLevel(lvl string) (Level, error) { return InfoLevel, nil case "debug": return DebugLevel, nil + case "trace": + return TraceLevel, nil } var l Level return l, fmt.Errorf("not a valid logrus Level: %q", lvl) } +// UnmarshalText implements encoding.TextUnmarshaler. +func (level *Level) UnmarshalText(text []byte) error { + l, err := ParseLevel(string(text)) + if err != nil { + return err + } + + *level = Level(l) + + return nil +} + // A constant exposing all logging levels var AllLevels = []Level{ PanicLevel, @@ -61,6 +77,7 @@ var AllLevels = []Level{ WarnLevel, InfoLevel, DebugLevel, + TraceLevel, } // These are the different logging levels. You can set the logging level to log @@ -69,7 +86,7 @@ const ( // PanicLevel level, highest level of severity. Logs and then calls panic with the // message passed to Debug, Info, ... PanicLevel Level = iota - // FatalLevel level. Logs and then calls `os.Exit(1)`. It will exit even if the + // FatalLevel level. Logs and then calls `logger.Exit(1)`. It will exit even if the // logging level is set to Panic. FatalLevel // ErrorLevel level. Logs. Used for errors that should definitely be noted. @@ -82,6 +99,8 @@ const ( InfoLevel // DebugLevel level. Usually only enabled when debugging. Very verbose logging. DebugLevel + // TraceLevel level. Designates finer-grained informational events than the Debug. + TraceLevel ) // Won't compile if StdLogger can't be realized by a log.Logger @@ -140,4 +159,20 @@ type FieldLogger interface { Errorln(args ...interface{}) Fatalln(args ...interface{}) Panicln(args ...interface{}) + + // IsDebugEnabled() bool + // IsInfoEnabled() bool + // IsWarnEnabled() bool + // IsErrorEnabled() bool + // IsFatalEnabled() bool + // IsPanicEnabled() bool +} + +// Ext1FieldLogger (the first extension to FieldLogger) is superfluous, it is +// here for consistancy. Do not use. Use Logger or Entry instead. +type Ext1FieldLogger interface { + FieldLogger + Tracef(format string, args ...interface{}) + Trace(args ...interface{}) + Traceln(args ...interface{}) } diff --git a/logrus_test.go b/logrus_test.go index 78cbc28..b12d71c 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -1,67 +1,93 @@ -package logrus +package logrus_test import ( "bytes" "encoding/json" - "strconv" - "strings" + "io/ioutil" + "os" + "path/filepath" "sync" "testing" + "time" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + . "github.com/sirupsen/logrus" + . "github.com/sirupsen/logrus/internal/testutils" ) -func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) { +// TestReportCaller verifies that when ReportCaller is set, the 'func' field +// is added, and when it is unset it is not set or modified +// Verify that functions within the Logrus package aren't considered when +// discovering the caller. +func TestReportCallerWhenConfigured(t *testing.T) { + LogAndAssertJSON(t, func(log *Logger) { + log.ReportCaller = false + log.Print("testNoCaller") + }, func(fields Fields) { + assert.Equal(t, "testNoCaller", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, nil, fields["func"]) + }) + + LogAndAssertJSON(t, func(log *Logger) { + log.ReportCaller = true + log.Print("testWithCaller") + }, func(fields Fields) { + assert.Equal(t, "testWithCaller", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestReportCallerWhenConfigured.func3", fields["func"]) + }) +} + +func logSomething(t *testing.T, message string) Fields { var buffer bytes.Buffer var fields Fields logger := New() logger.Out = &buffer logger.Formatter = new(JSONFormatter) + logger.ReportCaller = true - log(logger) + entry := logger.WithFields(Fields{ + "foo": "bar", + }) + + entry.Info(message) err := json.Unmarshal(buffer.Bytes(), &fields) assert.Nil(t, err) - assertions(fields) + return fields } -func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields map[string]string)) { - var buffer bytes.Buffer +// TestReportCallerHelperDirect - verify reference when logging from a regular function +func TestReportCallerHelperDirect(t *testing.T) { + fields := logSomething(t, "direct") - logger := New() - logger.Out = &buffer - logger.Formatter = &TextFormatter{ - DisableColors: true, - } + assert.Equal(t, "direct", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"]) +} - log(logger) +// TestReportCallerHelperDirect - verify reference when logging from a function called via pointer +func TestReportCallerHelperViaPointer(t *testing.T) { + fptr := logSomething + fields := fptr(t, "via pointer") - 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 := kvArr[1] - if kvArr[1][0] == '"' { - var err error - val, err = strconv.Unquote(val) - assert.NoError(t, err) - } - fields[key] = val - } - assertions(fields) + assert.Equal(t, "via pointer", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"]) } func TestPrint(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Print("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["level"], "info") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "info", fields["level"]) }) } @@ -69,8 +95,8 @@ func TestInfo(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Info("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["level"], "info") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "info", fields["level"]) }) } @@ -78,8 +104,8 @@ func TestWarn(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Warn("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["level"], "warning") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "warning", fields["level"]) }) } @@ -87,7 +113,7 @@ func TestInfolnShouldAddSpacesBetweenStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln("test", "test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test test") + assert.Equal(t, "test test", fields["msg"]) }) } @@ -95,7 +121,7 @@ func TestInfolnShouldAddSpacesBetweenStringAndNonstring(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln("test", 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test 10") + assert.Equal(t, "test 10", fields["msg"]) }) } @@ -103,7 +129,7 @@ func TestInfolnShouldAddSpacesBetweenTwoNonStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln(10, 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "10 10") + assert.Equal(t, "10 10", fields["msg"]) }) } @@ -111,7 +137,7 @@ func TestInfoShouldAddSpacesBetweenTwoNonStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln(10, 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "10 10") + assert.Equal(t, "10 10", fields["msg"]) }) } @@ -119,7 +145,7 @@ func TestInfoShouldNotAddSpacesBetweenStringAndNonstring(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Info("test", 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test10") + assert.Equal(t, "test10", fields["msg"]) }) } @@ -127,7 +153,7 @@ func TestInfoShouldNotAddSpacesBetweenStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Info("test", "test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "testtest") + assert.Equal(t, "testtest", fields["msg"]) }) } @@ -165,7 +191,7 @@ func TestUserSuppliedFieldDoesNotOverwriteDefaults(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("msg", "hello").Info("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") + assert.Equal(t, "test", fields["msg"]) }) } @@ -173,8 +199,8 @@ func TestUserSuppliedMsgFieldHasPrefix(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("msg", "hello").Info("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["fields.msg"], "hello") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "hello", fields["fields.msg"]) }) } @@ -182,7 +208,7 @@ func TestUserSuppliedTimeFieldHasPrefix(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("time", "hello").Info("test") }, func(fields Fields) { - assert.Equal(t, fields["fields.time"], "hello") + assert.Equal(t, "hello", fields["fields.time"]) }) } @@ -190,8 +216,8 @@ func TestUserSuppliedLevelFieldHasPrefix(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("level", 1).Info("test") }, func(fields Fields) { - assert.Equal(t, fields["level"], "info") - assert.Equal(t, fields["fields.level"], 1.0) // JSON has floats only + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, 1.0, fields["fields.level"]) // JSON has floats only }) } @@ -209,6 +235,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(time.RFC3339)) + }) +} + +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(time.RFC3339)) + 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(time.RFC3339)) + 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 @@ -235,13 +320,117 @@ func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) { err = json.Unmarshal(buffer.Bytes(), &fields) assert.NoError(t, err, "should have decoded second message") assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields") - assert.Equal(t, fields["msg"], "omg it is!") - assert.Equal(t, fields["context"], "eating raw fish") + assert.Equal(t, "omg it is!", fields["msg"]) + assert.Equal(t, "eating raw fish", fields["context"]) assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") } +func TestNestedLoggingReportsCorrectCaller(t *testing.T) { + var buffer bytes.Buffer + var fields Fields + + logger := New() + logger.Out = &buffer + logger.Formatter = new(JSONFormatter) + logger.ReportCaller = true + + llog := logger.WithField("context", "eating raw fish") + + llog.Info("looks delicious") + + err := json.Unmarshal(buffer.Bytes(), &fields) + require.NoError(t, err, "should have decoded first message") + assert.Equal(t, 6, len(fields), "should have msg/time/level/func/context fields") + assert.Equal(t, "looks delicious", fields["msg"]) + assert.Equal(t, "eating raw fish", fields["context"]) + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) + cwd, err := os.Getwd() + require.NoError(t, err) + assert.Equal(t, filepath.ToSlash(cwd+"/logrus_test.go:340"), filepath.ToSlash(fields["file"].(string))) + + buffer.Reset() + + logger.WithFields(Fields{ + "Clyde": "Stubblefield", + }).WithFields(Fields{ + "Jab'o": "Starks", + }).WithFields(Fields{ + "uri": "https://www.youtube.com/watch?v=V5DTznu-9v0", + }).WithFields(Fields{ + "func": "y drummer", + }).WithFields(Fields{ + "James": "Brown", + }).Print("The hardest workin' man in show business") + + err = json.Unmarshal(buffer.Bytes(), &fields) + assert.NoError(t, err, "should have decoded second message") + assert.Equal(t, 11, len(fields), "should have all builtin fields plus foo,bar,baz,...") + assert.Equal(t, "Stubblefield", fields["Clyde"]) + assert.Equal(t, "Starks", fields["Jab'o"]) + assert.Equal(t, "https://www.youtube.com/watch?v=V5DTznu-9v0", fields["uri"]) + assert.Equal(t, "y drummer", fields["fields.func"]) + assert.Equal(t, "Brown", fields["James"]) + assert.Equal(t, "The hardest workin' man in show business", fields["msg"]) + assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) + require.NoError(t, err) + assert.Equal(t, filepath.ToSlash(cwd+"/logrus_test.go:365"), filepath.ToSlash(fields["file"].(string))) + + logger.ReportCaller = false // return to default value +} + +func logLoop(iterations int, reportCaller bool) { + var buffer bytes.Buffer + + logger := New() + logger.Out = &buffer + logger.Formatter = new(JSONFormatter) + logger.ReportCaller = reportCaller + + for i := 0; i < iterations; i++ { + logger.Infof("round %d of %d", i, iterations) + } +} + +// Assertions for upper bounds to reporting overhead +func TestCallerReportingOverhead(t *testing.T) { + iterations := 5000 + before := time.Now() + logLoop(iterations, false) + during := time.Now() + logLoop(iterations, true) + after := time.Now() + + elapsedNotReporting := during.Sub(before).Nanoseconds() + elapsedReporting := after.Sub(during).Nanoseconds() + + maxDelta := 1 * time.Second + assert.WithinDuration(t, during, before, maxDelta, + "%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)", + iterations, maxDelta.Seconds(), elapsedNotReporting) + assert.WithinDuration(t, after, during, maxDelta, + "%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)", + iterations, maxDelta.Seconds(), elapsedReporting) +} + +// benchmarks for both with and without caller-function reporting +func BenchmarkWithoutCallerTracing(b *testing.B) { + for i := 0; i < b.N; i++ { + logLoop(1000, false) + } +} + +func BenchmarkWithCallerTracing(b *testing.B) { + for i := 0; i < b.N; i++ { + logLoop(1000, true) + } +} + func TestConvertLevelToString(t *testing.T) { + assert.Equal(t, "trace", TraceLevel.String()) assert.Equal(t, "debug", DebugLevel.String()) assert.Equal(t, "info", InfoLevel.String()) assert.Equal(t, "warning", WarnLevel.String()) @@ -307,10 +496,31 @@ func TestParseLevel(t *testing.T) { assert.Nil(t, err) assert.Equal(t, DebugLevel, l) + l, err = ParseLevel("trace") + assert.Nil(t, err) + assert.Equal(t, TraceLevel, l) + + l, err = ParseLevel("TRACE") + assert.Nil(t, err) + assert.Equal(t, TraceLevel, l) + l, err = ParseLevel("invalid") assert.Equal(t, "not a valid logrus Level: \"invalid\"", err.Error()) } +func TestUnmarshalText(t *testing.T) { + var u Level + for _, level := range AllLevels { + t.Run(level.String(), func(t *testing.T) { + assert.NoError(t, u.UnmarshalText([]byte(level.String()))) + assert.Equal(t, level, u) + }) + } + t.Run("invalid", func(t *testing.T) { + assert.Error(t, u.UnmarshalText([]byte("invalid"))) + }) +} + func TestGetSetLevelRace(t *testing.T) { wg := sync.WaitGroup{} for i := 0; i < 100; i++ { @@ -343,10 +553,52 @@ 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) { +func TestLogrusInterfaces(t *testing.T) { var buffer bytes.Buffer - fn := func(l FieldLogger) { + // This verifies FieldLogger and Ext1FieldLogger work as designed. + // Please don't use them. Use Logger and Entry directly. + fn := func(xl Ext1FieldLogger) { + var l FieldLogger = xl b := l.WithField("key", "value") b.Debug("Test") } @@ -384,3 +636,81 @@ func TestEntryWriter(t *testing.T) { assert.Equal(t, fields["foo"], "bar") assert.Equal(t, fields["level"], "warning") } + +func TestLogLevelEnabled(t *testing.T) { + log := New() + log.SetLevel(PanicLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, false, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, false, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, false, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(FatalLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, false, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, false, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(ErrorLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, false, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(WarnLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(InfoLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, true, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(DebugLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, true, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, true, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(TraceLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, true, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, true, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, true, log.IsLevelEnabled(TraceLevel)) +} + +func TestReportCallerOnTextFormatter(t *testing.T) { + l := New() + + l.Formatter.(*TextFormatter).ForceColors = true + l.Formatter.(*TextFormatter).DisableColors = false + l.WithFields(Fields{"func": "func", "file": "file"}).Info("test") + + l.Formatter.(*TextFormatter).ForceColors = false + l.Formatter.(*TextFormatter).DisableColors = true + l.WithFields(Fields{"func": "func", "file": "file"}).Info("test") +} diff --git a/terminal_bsd.go b/terminal_bsd.go deleted file mode 100644 index 4880d13..0000000 --- a/terminal_bsd.go +++ /dev/null @@ -1,10 +0,0 @@ -// +build darwin freebsd openbsd netbsd dragonfly -// +build !appengine,!gopherjs - -package logrus - -import "golang.org/x/sys/unix" - -const ioctlReadTermios = unix.TIOCGETA - -type Termios unix.Termios 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..cf309d6 100644 --- a/terminal_check_notappengine.go +++ b/terminal_check_notappengine.go @@ -1,4 +1,4 @@ -// +build !appengine,!gopherjs +// +build !appengine,!js,!windows package logrus diff --git a/terminal_check_windows.go b/terminal_check_windows.go new file mode 100644 index 0000000..3b9d286 --- /dev/null +++ b/terminal_check_windows.go @@ -0,0 +1,20 @@ +// +build !appengine,!js,windows + +package logrus + +import ( + "io" + "os" + "syscall" +) + +func checkIfTerminal(w io.Writer) bool { + switch v := w.(type) { + case *os.File: + var mode uint32 + err := syscall.GetConsoleMode(syscall.Handle(v.Fd()), &mode) + return err == nil + default: + return false + } +} diff --git a/terminal_linux.go b/terminal_linux.go deleted file mode 100644 index f29a009..0000000 --- a/terminal_linux.go +++ /dev/null @@ -1,14 +0,0 @@ -// Based on ssh/terminal: -// Copyright 2013 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build !appengine,!gopherjs - -package logrus - -import "golang.org/x/sys/unix" - -const ioctlReadTermios = unix.TCGETS - -type Termios unix.Termios diff --git a/terminal_notwindows.go b/terminal_notwindows.go new file mode 100644 index 0000000..3dbd237 --- /dev/null +++ b/terminal_notwindows.go @@ -0,0 +1,8 @@ +// +build !windows + +package logrus + +import "io" + +func initTerminal(w io.Writer) { +} diff --git a/terminal_windows.go b/terminal_windows.go new file mode 100644 index 0000000..b4ef528 --- /dev/null +++ b/terminal_windows.go @@ -0,0 +1,18 @@ +// +build !appengine,!js,windows + +package logrus + +import ( + "io" + "os" + "syscall" + + sequences "github.com/konsorten/go-windows-terminal-sequences" +) + +func initTerminal(w io.Writer) { + switch v := w.(type) { + case *os.File: + sequences.EnableVirtualTerminalProcessing(syscall.Handle(v.Fd()), true) + } +} diff --git a/text_formatter.go b/text_formatter.go index 3e55040..49ec92f 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,6 +55,9 @@ type TextFormatter struct { // be desired. DisableSorting bool + // The keys sorting function, when uninitialized it uses sort.Strings. + SortingFunc func([]string) + // Disables the truncation of the level text to 4 characters. DisableLevelTruncation bool @@ -69,26 +76,74 @@ type TextFormatter struct { // FieldKeyMsg: "@message"}} FieldMap FieldMap - sync.Once + terminalInitOnce sync.Once } func (f *TextFormatter) init(entry *Entry) { if entry.Logger != nil { f.isTerminal = checkIfTerminal(entry.Logger.Out) + + if f.isTerminal { + initTerminal(entry.Logger.Out) + } } } +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) { - prefixFieldClashes(entry.Data, f.FieldMap) + prefixFieldClashes(entry.Data, f.FieldMap, entry.HasCaller()) keys := make([]string, 0, len(entry.Data)) for k := range entry.Data { keys = append(keys, k) } + fixedKeys := make([]string, 0, 4+len(entry.Data)) + if !f.DisableTimestamp { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyTime)) + } + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLevel)) + if entry.Message != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyMsg)) + } + if entry.err != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLogrusError)) + } + if entry.HasCaller() { + fixedKeys = append(fixedKeys, + f.FieldMap.resolve(FieldKeyFunc), f.FieldMap.resolve(FieldKeyFile)) + } + if !f.DisableSorting { - sort.Strings(keys) + if f.SortingFunc == nil { + sort.Strings(keys) + fixedKeys = append(fixedKeys, keys...) + } else { + if !f.isColored() { + fixedKeys = append(fixedKeys, keys...) + f.SortingFunc(fixedKeys) + } else { + f.SortingFunc(keys) + } + } + } else { + fixedKeys = append(fixedKeys, keys...) } var b *bytes.Buffer @@ -98,26 +153,34 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { b = &bytes.Buffer{} } - f.Do(func() { f.init(entry) }) - - isColored := (f.ForceColors || f.isTerminal) && !f.DisableColors + f.terminalInitOnce.Do(func() { f.init(entry) }) 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, f.FieldMap.resolve(FieldKeyTime), entry.Time.Format(timestampFormat)) - } - f.appendKeyValue(b, f.FieldMap.resolve(FieldKeyLevel), entry.Level.String()) - if entry.Message != "" { - f.appendKeyValue(b, f.FieldMap.resolve(FieldKeyMsg), entry.Message) - } - for _, key := range keys { - f.appendKeyValue(b, key, entry.Data[key]) + for _, key := range fixedKeys { + var value interface{} + switch { + case key == f.FieldMap.resolve(FieldKeyTime): + value = entry.Time.Format(timestampFormat) + case key == f.FieldMap.resolve(FieldKeyLevel): + value = entry.Level.String() + case key == f.FieldMap.resolve(FieldKeyMsg): + value = entry.Message + case key == f.FieldMap.resolve(FieldKeyLogrusError): + value = entry.err + case key == f.FieldMap.resolve(FieldKeyFunc) && entry.HasCaller(): + value = entry.Caller.Function + case key == f.FieldMap.resolve(FieldKeyFile) && entry.HasCaller(): + value = fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + default: + value = entry.Data[key] + } + f.appendKeyValue(b, key, value) } } @@ -128,7 +191,7 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []string, timestampFormat string) { var levelColor int switch entry.Level { - case DebugLevel: + case DebugLevel, TraceLevel: levelColor = gray case WarnLevel: levelColor = yellow @@ -143,12 +206,23 @@ 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") + + caller := "" + + if entry.HasCaller() { + caller = fmt.Sprintf("%s:%d %s()", + entry.Caller.File, entry.Caller.Line, entry.Caller.Function) + } + if f.DisableTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m %-44s ", levelColor, levelText, entry.Message) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m%s %-44s ", levelColor, levelText, caller, entry.Message) } else if !f.FullTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), entry.Message) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d]%s %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), caller, entry.Message) } else { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %-44s ", levelColor, levelText, entry.Time.Format(timestampFormat), entry.Message) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]%s %-44s ", levelColor, levelText, entry.Time.Format(timestampFormat), caller, entry.Message) } for _, k := range keys { v := entry.Data[k] diff --git a/text_formatter_test.go b/text_formatter_test.go index 921d052..b0d3a91 100644 --- a/text_formatter_test.go +++ b/text_formatter_test.go @@ -4,11 +4,14 @@ import ( "bytes" "errors" "fmt" + "os" + "sort" "strings" "testing" "time" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func TestFormatting(t *testing.T) { @@ -177,6 +180,29 @@ 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, @@ -216,5 +242,239 @@ func TestTextFormatterFieldMap(t *testing.T) { "Formatted output doesn't respect FieldMap") } -// TODO add tests for sorting etc., this requires a parser for the text -// formatter output. +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) + }) + } +} + +func TestCustomSorting(t *testing.T) { + formatter := &TextFormatter{ + DisableColors: true, + SortingFunc: func(keys []string) { + sort.Slice(keys, func(i, j int) bool { + if keys[j] == "prefix" { + return false + } + if keys[i] == "prefix" { + return true + } + return strings.Compare(keys[i], keys[j]) == -1 + }) + }, + } + + entry := &Entry{ + Message: "Testing custom sort function", + Time: time.Now(), + Level: InfoLevel, + Data: Fields{ + "test": "testvalue", + "prefix": "the application prefix", + "blablabla": "blablabla", + }, + } + b, err := formatter.Format(entry) + require.NoError(t, err) + require.True(t, strings.HasPrefix(string(b), "prefix="), "format output is %q", string(b)) +} diff --git a/writer.go b/writer.go index 7bdebed..9e1f751 100644 --- a/writer.go +++ b/writer.go @@ -24,6 +24,8 @@ func (entry *Entry) WriterLevel(level Level) *io.PipeWriter { var printFunc func(args ...interface{}) switch level { + case TraceLevel: + printFunc = entry.Trace case DebugLevel: printFunc = entry.Debug case InfoLevel: