From 93af604ba7774ca16474f3485ab6fcf084606fe0 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Fri, 25 Nov 2016 19:02:56 -0800 Subject: [PATCH 01/25] First cut at adding calling method If log.SetReportMethod(true) then method=PACKAGE.FUNCTION will be added as a field to log lines. eg: time="2016-11-25T19:04:43-08:00" level=info method=main msg="log testing" TODO: documentation, examples --- README.md | 7 ++++ alt_exit_test.go | 20 ++++++++++-- entry.go | 47 +++++++++++++++++++++++++-- exported.go | 16 +++++++++ formatter.go | 10 +++++- json_formatter.go | 20 +++++++----- json_formatter_test.go | 48 +++++++++++++++++++++++++++ logger.go | 13 +++++--- logrus_test.go | 73 ++++++++++++++++++++++++++++++++++++++++++ text_formatter.go | 14 ++++++-- 10 files changed, 248 insertions(+), 20 deletions(-) diff --git a/README.md b/README.md index f9cfb0a..275c113 100644 --- a/README.md +++ b/README.md @@ -45,6 +45,13 @@ time="2015-03-26T01:27:38-04:00" level=panic msg="It's over 9000!" animal=orca s 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: +``` + log.SetFormatter(&log.TextFormatter{ + DisableColors: true, + FullTimestamp: true, + }) +``` #### Example diff --git a/alt_exit_test.go b/alt_exit_test.go index 022b778..5763c60 100644 --- a/alt_exit_test.go +++ b/alt_exit_test.go @@ -3,6 +3,8 @@ package logrus import ( "io/ioutil" "os/exec" + "runtime" + "strings" "testing" "time" ) @@ -17,6 +19,9 @@ func TestRegister(t *testing.T) { func TestHandler(t *testing.T) { gofile := "/tmp/testprog.go" + testprog := testprogleader + testprog = append(testprog, getPackage()...) + testprog = append(testprog, testprogtrailer...) if err := ioutil.WriteFile(gofile, testprog, 0666); err != nil { t.Fatalf("can't create go file") } @@ -38,13 +43,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 4edbe7a..1e721ce 100644 --- a/entry.go +++ b/entry.go @@ -4,6 +4,9 @@ import ( "bytes" "fmt" "os" + "regexp" + "runtime" + "strings" "sync" "time" ) @@ -37,6 +40,9 @@ type Entry struct { // Level the log entry was logged at: Debug, Info, Warn, Error, Fatal or Panic Level Level + // Calling method, with package name + Method string + // Message passed to Debug, Info, Warn, Error, Fatal or Panic Message string @@ -47,8 +53,8 @@ type Entry struct { func NewEntry(logger *Logger) *Entry { return &Entry{ Logger: logger, - // Default is three 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), } } @@ -85,6 +91,39 @@ func (entry *Entry) WithFields(fields Fields) *Entry { return &Entry{Logger: entry.Logger, Data: data} } +// getCaller retrieves the name of the first non-logrus calling function +func getCaller() (method string) { + // Restrict the lookback to 25 frames - if it's further than that, report UNKNOWN + pcs := make([]uintptr, 25) + + // the first non-logrus caller is at least three frames away + depth := runtime.Callers(3, pcs) + for i := 0; i < depth; i++ { + fullFuncName := runtime.FuncForPC(pcs[i]).Name() + idx := strings.LastIndex(fullFuncName, "/") + 1 + if idx > 0 { + fullFuncName = fullFuncName[idx:] + } + + matched, err := regexp.MatchString("logrus.*", fullFuncName) + if err != nil { + return "CALLER_LOOKUP_FAILED" + } + + // If the caller isn't part of logrus, we're done + if !matched { + if fullFuncName == "main.main" { + return "main" + } else { + return fullFuncName + } + } + } + + // if we got here, we failed to find the caller's context + return "UNKNOWN_CALLER" +} + // 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) { @@ -92,7 +131,9 @@ func (entry Entry) log(level Level, msg string) { entry.Time = time.Now() entry.Level = level entry.Message = msg - + if ReportMethod() { + entry.Method = getCaller() + } if err := entry.Logger.Hooks.Fire(level, &entry); err != nil { entry.Logger.mu.Lock() fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) diff --git a/exported.go b/exported.go index 9a0120a..7a02d7c 100644 --- a/exported.go +++ b/exported.go @@ -27,6 +27,22 @@ func SetFormatter(formatter Formatter) { std.Formatter = formatter } +// SetReportMethod sets whether to include calling method and line as +// fields +func SetReportMethod(include bool) { + std.mu.Lock() + defer std.mu.Unlock() + std.ReportMethod = include +} + +// ReportMethod sets whether to include calling method and line as +// fields +func ReportMethod() bool { + std.mu.Lock() + defer std.mu.Unlock() + return std.ReportMethod +} + // SetLevel sets the standard logger level. func SetLevel(level Level) { std.mu.Lock() diff --git a/formatter.go b/formatter.go index b5fbe93..c48e02f 100644 --- a/formatter.go +++ b/formatter.go @@ -2,6 +2,7 @@ package logrus import "time" +// DefaultTimestampFormat is YYYY-mm-DDTHH:MM:SS-TZ const DefaultTimestampFormat = time.RFC3339 // The Formatter interface is used to implement a custom Formatter. It takes an @@ -18,7 +19,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`, `method` and `level` fields when // dumping it. If this code wasn't there doing: // // logrus.WithField("level", 1).Info("hello") @@ -42,4 +43,11 @@ func prefixFieldClashes(data Fields) { if l, ok := data["level"]; ok { data["fields.level"] = l } + + // If ReportMethod is not set, 'method' will not conflict. + if ReportMethod() { + if l, ok := data["method"]; ok { + data["fields.method"] = l + } + } } diff --git a/json_formatter.go b/json_formatter.go index f3729bf..a84cc15 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -9,9 +9,10 @@ type fieldKey string type FieldMap map[fieldKey]string const ( - FieldKeyMsg = "msg" - FieldKeyLevel = "level" - FieldKeyTime = "time" + FieldKeyMsg = "msg" + FieldKeyLevel = "level" + FieldKeyTime = "time" + FieldKeyMethod = "method" ) func (f FieldMap) resolve(key fieldKey) string { @@ -30,16 +31,17 @@ type JSONFormatter struct { // As an example: // formatter := &JSONFormatter{ // FieldMap: FieldMap{ - // FieldKeyTime: "@timestamp", - // FieldKeyLevel: "@level", - // FieldKeyLevel: "@message", + // FieldKeyTime: "@timestamp", + // FieldKeyLevel: "@level", + // FieldKeyMsg: "@message", + // FieldKeyMethod: "@caller", // }, // } FieldMap FieldMap } 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: @@ -60,7 +62,9 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { 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 ReportMethod() { + data[f.FieldMap.resolve(FieldKeyMethod)] = entry.Method + } serialized, err := json.Marshal(data) if err != nil { return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err) diff --git a/json_formatter_test.go b/json_formatter_test.go index 5baa93e..dc09bfe 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -169,3 +169,51 @@ func TestJSONTimeKey(t *testing.T) { t.Fatal("Expected JSON to format time key") } } + +func TestFieldDoesNotClashWithMethod(t *testing.T) { + SetReportMethod(false) + formatter := &JSONFormatter{} + + b, err := formatter.Format(WithField("method", "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["method"] != "howdy pardner" { + t.Fatal("method field replaced when ReportMethod=false") + } +} + +func TestFieldClashWithMethod(t *testing.T) { + SetReportMethod(true) + formatter := &JSONFormatter{} + + b, err := formatter.Format(WithField("method", "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["fields.method"] != "howdy pardner" { + t.Fatalf("fields.method not set to original method field when ReportMethod=true (got '%s')", + entry["fields.method"]) + } + + if entry["method"] != "" { // since we didn't actually log, it's set to the empty string + t.Fatalf("method not set as expected when ReportMethod=true (got '%s')", + entry["method"]) + } + + SetReportMethod(false) // return to default value +} diff --git a/logger.go b/logger.go index b769f3d..64967c4 100644 --- a/logger.go +++ b/logger.go @@ -22,6 +22,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) + ReportMethod 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. `logrus.Debug` is useful in @@ -67,10 +71,11 @@ 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, + ReportMethod: false, } } diff --git a/logrus_test.go b/logrus_test.go index bfc4780..2ba154e 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -56,6 +56,30 @@ func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields ma assertions(fields) } +// TestReportMethod verifies that when ReportMethod is set, the 'method' field +// is added, and when it is unset it is not set or modified +func TestReportMethod(t *testing.T) { + LogAndAssertJSON(t, func(log *Logger) { + SetReportMethod(false) + log.Print("testNoCaller") + }, func(fields Fields) { + assert.Equal(t, fields["msg"], "testNoCaller") + assert.Equal(t, fields["level"], "info") + assert.Equal(t, fields["method"], nil) + }) + + LogAndAssertJSON(t, func(log *Logger) { + SetReportMethod(true) + log.Print("testWithCaller") + }, func(fields Fields) { + assert.Equal(t, fields["msg"], "testWithCaller") + assert.Equal(t, fields["level"], "info") + assert.Equal(t, fields["method"], "testing.tRunner") + }) + + SetReportMethod(false) // return to default value +} + func TestPrint(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Print("test") @@ -241,6 +265,55 @@ func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) { } +func TestNestedLoggingReportsCorrectCaller(t *testing.T) { + var buffer bytes.Buffer + var fields Fields + + SetReportMethod(true) + logger := New() + logger.Out = &buffer + logger.Formatter = new(JSONFormatter) + + llog := logger.WithField("context", "eating raw fish") + + llog.Info("looks delicious") + + err := json.Unmarshal(buffer.Bytes(), &fields) + assert.NoError(t, err, "should have decoded first message") + assert.Equal(t, len(fields), 5, "should have msg/time/level/method/context fields") + assert.Equal(t, fields["msg"], "looks delicious") + assert.Equal(t, fields["context"], "eating raw fish") + assert.Equal(t, fields["method"], "testing.tRunner") + + buffer.Reset() + + logger.WithFields(Fields{ + "foo": "a", + }).WithFields(Fields{ + "bar": "b", + }).WithFields(Fields{ + "baz": "c", + }).WithFields(Fields{ + "method": "man", + }).WithFields(Fields{ + "clan": "Wu Tang", + }).Print("omg it is!") + + err = json.Unmarshal(buffer.Bytes(), &fields) + assert.NoError(t, err, "should have decoded second message") + assert.Equal(t, 10, len(fields), "should have all builtin fields plus foo,bar,baz") + assert.Equal(t, "omg it is!", fields["msg"]) + assert.Equal(t, "a", fields["foo"]) + assert.Equal(t, "b", fields["bar"]) + assert.Equal(t, "c", fields["baz"]) + assert.Equal(t, "man", fields["fields.method"]) + assert.Equal(t, "Wu Tang", fields["clan"]) + assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") + assert.Equal(t, "testing.tRunner", fields["method"]) + + SetReportMethod(false) // return to default value +} + func TestConvertLevelToString(t *testing.T) { assert.Equal(t, "debug", DebugLevel.String()) assert.Equal(t, "info", InfoLevel.String()) diff --git a/text_formatter.go b/text_formatter.go index 9114b3c..4b3cc62 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -88,6 +88,9 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) } f.appendKeyValue(b, "level", entry.Level.String()) + if ReportMethod() { + f.appendKeyValue(b, "method", entry.Method) + } if entry.Message != "" { f.appendKeyValue(b, "msg", entry.Message) } @@ -115,10 +118,17 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin levelText := strings.ToUpper(entry.Level.String())[0:4] + caller := "" + if ReportMethod() { + caller = fmt.Sprintf(" %s()", entry.Method) + } + if !f.FullTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, miniTS(), entry.Message) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d]%s %-44s ", levelColor, levelText, + miniTS(), 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] From 473c3448abc37edc827ade029c8ee302b207b2a6 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Mon, 28 Nov 2016 13:43:38 -0800 Subject: [PATCH 02/25] Add README notes and CHANGELOG entries documentation for usage of the new optional calling-method logging --- CHANGELOG.md | 4 ++++ README.md | 18 +++++++++++++++++- 2 files changed, 21 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f2c2bc2..0d84a2f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,7 @@ +# 0.11.0 + +* feature: Add optional logging of caller method + # 0.10.0 * feature: Add a test hook (#180) diff --git a/README.md b/README.md index 275c113..57f15e4 100644 --- a/README.md +++ b/README.md @@ -43,9 +43,9 @@ 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: + ``` log.SetFormatter(&log.TextFormatter{ DisableColors: true, @@ -53,6 +53,22 @@ To ensure this behaviour even if a TTY is attached, set your formatter as follow }) ``` +If you wish to add the calling method as a field, instruct the logger via: +``` +log.SetReportMethod(true) +``` +This adds the caller as 'method' like so: + +```json +{"animal":"penguin","level":"fatal","method":"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=arcticcreatures.migrate msg="a penguin swims by" animal=penguin + +``` #### Example The simplest way to use Logrus is simply the package-level exported logger: From 8161d932a1c23cea2db63cc7cccbc00e78de48f2 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Mon, 28 Nov 2016 14:47:38 -0800 Subject: [PATCH 03/25] performance: precompile regex before iterating --- entry.go | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/entry.go b/entry.go index 1e721ce..290232a 100644 --- a/entry.go +++ b/entry.go @@ -96,6 +96,11 @@ func getCaller() (method string) { // Restrict the lookback to 25 frames - if it's further than that, report UNKNOWN pcs := make([]uintptr, 25) + matchesLogrus, err := regexp.Compile("logrus.*") + if err != nil { + return "CALLER_LOOKUP_FAILED" + } + // the first non-logrus caller is at least three frames away depth := runtime.Callers(3, pcs) for i := 0; i < depth; i++ { @@ -105,10 +110,7 @@ func getCaller() (method string) { fullFuncName = fullFuncName[idx:] } - matched, err := regexp.MatchString("logrus.*", fullFuncName) - if err != nil { - return "CALLER_LOOKUP_FAILED" - } + matched := matchesLogrus.MatchString(fullFuncName) // If the caller isn't part of logrus, we're done if !matched { From 1e214504085248b77a41d97e90cc9903cc524005 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Mon, 28 Nov 2016 16:22:33 -0800 Subject: [PATCH 04/25] push compilation even higher, to reduce to one call --- entry.go | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/entry.go b/entry.go index 290232a..b7f4e9c 100644 --- a/entry.go +++ b/entry.go @@ -13,12 +13,17 @@ import ( var bufferPool *sync.Pool +// regex for validation is external, to reduce compilation overhead +var matchesLogrus *regexp.Regexp + func init() { bufferPool = &sync.Pool{ New: func() interface{} { return new(bytes.Buffer) }, } + + matchesLogrus, _ = regexp.Compile("logrus.*") } // Defines the key when adding errors using WithError. @@ -51,11 +56,13 @@ type Entry struct { } func NewEntry(logger *Logger) *Entry { - return &Entry{ + entry := &Entry{ Logger: logger, // Default is three fields, plus one optional. Give a little extra room. Data: make(Fields, 6), } + + return entry } // Returns the string representation from the reader and ultimately the @@ -96,11 +103,6 @@ func getCaller() (method string) { // Restrict the lookback to 25 frames - if it's further than that, report UNKNOWN pcs := make([]uintptr, 25) - matchesLogrus, err := regexp.Compile("logrus.*") - if err != nil { - return "CALLER_LOOKUP_FAILED" - } - // the first non-logrus caller is at least three frames away depth := runtime.Callers(3, pcs) for i := 0; i < depth; i++ { From 348bace2692cddf1f24a90f452348b1eecda6400 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Tue, 29 Nov 2016 09:35:34 -0800 Subject: [PATCH 05/25] doc updates, and relabel ReportMethod in the Logrus context it's the caller, so use that internally. Label stays as 'method' since in the context of the log event that seems more correct. --- README.md | 2 +- entry.go | 6 +++--- exported.go | 14 ++++++-------- formatter.go | 4 ++-- json_formatter.go | 8 ++++---- json_formatter_test.go | 16 ++++++++-------- logger.go | 4 ++-- logrus_test.go | 14 +++++++------- text_formatter.go | 8 ++++---- 9 files changed, 37 insertions(+), 39 deletions(-) diff --git a/README.md b/README.md index 57f15e4..25cc2c5 100644 --- a/README.md +++ b/README.md @@ -55,7 +55,7 @@ To ensure this behaviour even if a TTY is attached, set your formatter as follow If you wish to add the calling method as a field, instruct the logger via: ``` -log.SetReportMethod(true) +log.SetReportCaller(true) ``` This adds the caller as 'method' like so: diff --git a/entry.go b/entry.go index b7f4e9c..7949e1f 100644 --- a/entry.go +++ b/entry.go @@ -46,7 +46,7 @@ type Entry struct { Level Level // Calling method, with package name - Method string + Caller string // Message passed to Debug, Info, Warn, Error, Fatal or Panic Message string @@ -135,8 +135,8 @@ func (entry Entry) log(level Level, msg string) { entry.Time = time.Now() entry.Level = level entry.Message = msg - if ReportMethod() { - entry.Method = getCaller() + if ReportCaller() { + entry.Caller = getCaller() } if err := entry.Logger.Hooks.Fire(level, &entry); err != nil { entry.Logger.mu.Lock() diff --git a/exported.go b/exported.go index 7a02d7c..356d4a9 100644 --- a/exported.go +++ b/exported.go @@ -27,20 +27,18 @@ func SetFormatter(formatter Formatter) { std.Formatter = formatter } -// SetReportMethod sets whether to include calling method and line as -// fields -func SetReportMethod(include bool) { +// SetReportCaller sets whether to include the calling method as a field +func SetReportCaller(include bool) { std.mu.Lock() defer std.mu.Unlock() - std.ReportMethod = include + std.ReportCaller = include } -// ReportMethod sets whether to include calling method and line as -// fields -func ReportMethod() bool { +// ReportCaller returns the 'include calling method' state +func ReportCaller() bool { std.mu.Lock() defer std.mu.Unlock() - return std.ReportMethod + return std.ReportCaller } // SetLevel sets the standard logger level. diff --git a/formatter.go b/formatter.go index c48e02f..9e94689 100644 --- a/formatter.go +++ b/formatter.go @@ -44,8 +44,8 @@ func prefixFieldClashes(data Fields) { data["fields.level"] = l } - // If ReportMethod is not set, 'method' will not conflict. - if ReportMethod() { + // If Reportmethod is not set, 'method' will not conflict. + if ReportCaller() { if l, ok := data["method"]; ok { data["fields.method"] = l } diff --git a/json_formatter.go b/json_formatter.go index a84cc15..2bb3a6a 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -12,7 +12,7 @@ const ( FieldKeyMsg = "msg" FieldKeyLevel = "level" FieldKeyTime = "time" - FieldKeyMethod = "method" + FieldKeyCaller = "method" ) func (f FieldMap) resolve(key fieldKey) string { @@ -34,7 +34,7 @@ type JSONFormatter struct { // FieldKeyTime: "@timestamp", // FieldKeyLevel: "@level", // FieldKeyMsg: "@message", - // FieldKeyMethod: "@caller", + // FieldKeyCaller: "@caller", // }, // } FieldMap FieldMap @@ -62,8 +62,8 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { 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 ReportMethod() { - data[f.FieldMap.resolve(FieldKeyMethod)] = entry.Method + if ReportCaller() { + data[f.FieldMap.resolve(FieldKeyCaller)] = entry.Caller } serialized, err := json.Marshal(data) if err != nil { diff --git a/json_formatter_test.go b/json_formatter_test.go index dc09bfe..ab52095 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -170,8 +170,8 @@ func TestJSONTimeKey(t *testing.T) { } } -func TestFieldDoesNotClashWithMethod(t *testing.T) { - SetReportMethod(false) +func TestFieldDoesNotClashWithCaller(t *testing.T) { + SetReportCaller(false) formatter := &JSONFormatter{} b, err := formatter.Format(WithField("method", "howdy pardner")) @@ -186,12 +186,12 @@ func TestFieldDoesNotClashWithMethod(t *testing.T) { } if entry["method"] != "howdy pardner" { - t.Fatal("method field replaced when ReportMethod=false") + t.Fatal("method field replaced when ReportCaller=false") } } -func TestFieldClashWithMethod(t *testing.T) { - SetReportMethod(true) +func TestFieldClashWithCaller(t *testing.T) { + SetReportCaller(true) formatter := &JSONFormatter{} b, err := formatter.Format(WithField("method", "howdy pardner")) @@ -206,14 +206,14 @@ func TestFieldClashWithMethod(t *testing.T) { } if entry["fields.method"] != "howdy pardner" { - t.Fatalf("fields.method not set to original method field when ReportMethod=true (got '%s')", + t.Fatalf("fields.method not set to original method field when ReportCaller=true (got '%s')", entry["fields.method"]) } if entry["method"] != "" { // since we didn't actually log, it's set to the empty string - t.Fatalf("method not set as expected when ReportMethod=true (got '%s')", + t.Fatalf("method not set as expected when ReportCaller=true (got '%s')", entry["method"]) } - SetReportMethod(false) // return to default value + SetReportCaller(false) // return to default value } diff --git a/logger.go b/logger.go index 64967c4..ddab68a 100644 --- a/logger.go +++ b/logger.go @@ -24,7 +24,7 @@ type Logger struct { Formatter Formatter //Flag for whether to log caller info (off by default) - ReportMethod bool + 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 @@ -75,7 +75,7 @@ func New() *Logger { Formatter: new(TextFormatter), Hooks: make(LevelHooks), Level: InfoLevel, - ReportMethod: false, + ReportCaller: false, } } diff --git a/logrus_test.go b/logrus_test.go index 2ba154e..760a24b 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -56,11 +56,11 @@ func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields ma assertions(fields) } -// TestReportMethod verifies that when ReportMethod is set, the 'method' field +// TestReportCaller verifies that when ReportCaller is set, the 'method' field // is added, and when it is unset it is not set or modified -func TestReportMethod(t *testing.T) { +func TestReportCaller(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { - SetReportMethod(false) + SetReportCaller(false) log.Print("testNoCaller") }, func(fields Fields) { assert.Equal(t, fields["msg"], "testNoCaller") @@ -69,7 +69,7 @@ func TestReportMethod(t *testing.T) { }) LogAndAssertJSON(t, func(log *Logger) { - SetReportMethod(true) + SetReportCaller(true) log.Print("testWithCaller") }, func(fields Fields) { assert.Equal(t, fields["msg"], "testWithCaller") @@ -77,7 +77,7 @@ func TestReportMethod(t *testing.T) { assert.Equal(t, fields["method"], "testing.tRunner") }) - SetReportMethod(false) // return to default value + SetReportCaller(false) // return to default value } func TestPrint(t *testing.T) { @@ -269,7 +269,7 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { var buffer bytes.Buffer var fields Fields - SetReportMethod(true) + SetReportCaller(true) logger := New() logger.Out = &buffer logger.Formatter = new(JSONFormatter) @@ -311,7 +311,7 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") assert.Equal(t, "testing.tRunner", fields["method"]) - SetReportMethod(false) // return to default value + SetReportCaller(false) // return to default value } func TestConvertLevelToString(t *testing.T) { diff --git a/text_formatter.go b/text_formatter.go index 4b3cc62..b003451 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -88,8 +88,8 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) } f.appendKeyValue(b, "level", entry.Level.String()) - if ReportMethod() { - f.appendKeyValue(b, "method", entry.Method) + if ReportCaller() { + f.appendKeyValue(b, "method", entry.Caller) } if entry.Message != "" { f.appendKeyValue(b, "msg", entry.Message) @@ -119,8 +119,8 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin levelText := strings.ToUpper(entry.Level.String())[0:4] caller := "" - if ReportMethod() { - caller = fmt.Sprintf(" %s()", entry.Method) + if ReportCaller() { + caller = fmt.Sprintf(" %s()", entry.Caller) } if !f.FullTimestamp { From 05a8f4db95032b1209e9badae15584fae216e59d Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 30 Nov 2016 10:47:03 -0800 Subject: [PATCH 06/25] fix test description --- logrus_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logrus_test.go b/logrus_test.go index 760a24b..ec31850 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -301,7 +301,7 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { err = json.Unmarshal(buffer.Bytes(), &fields) assert.NoError(t, err, "should have decoded second message") - assert.Equal(t, 10, len(fields), "should have all builtin fields plus foo,bar,baz") + assert.Equal(t, 10, len(fields), "should have all builtin fields plus foo,bar,baz,...") assert.Equal(t, "omg it is!", fields["msg"]) assert.Equal(t, "a", fields["foo"]) assert.Equal(t, "b", fields["bar"]) From 4575b7a64d0ff75887a6433464fb476d8725ac71 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 30 Nov 2016 11:36:48 -0800 Subject: [PATCH 07/25] revert slight added complexity in NewEntry() --- entry.go | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/entry.go b/entry.go index 7949e1f..850b958 100644 --- a/entry.go +++ b/entry.go @@ -56,13 +56,11 @@ type Entry struct { } func NewEntry(logger *Logger) *Entry { - entry := &Entry{ + return &Entry{ Logger: logger, // Default is three fields, plus one optional. Give a little extra room. Data: make(Fields, 6), } - - return entry } // Returns the string representation from the reader and ultimately the From a5c845c2247a1798ddfb903dd3af2d5e062f6c7e Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 30 Nov 2016 14:07:10 -0800 Subject: [PATCH 08/25] responses to review comments - empty string as marker for failure to discover calling function - tighten up logger usage - don't rely on std logger internally Also fix ordering of expected/got in logrus_test.go to ensure correct output form test failures. --- entry.go | 4 +-- exported.go | 10 ++----- formatter.go | 6 ++-- json_formatter.go | 10 +++++-- json_formatter_test.go | 1 + logrus_test.go | 68 ++++++++++++++++++++---------------------- text_formatter.go | 17 +++++++++-- 7 files changed, 63 insertions(+), 53 deletions(-) diff --git a/entry.go b/entry.go index 850b958..9e86687 100644 --- a/entry.go +++ b/entry.go @@ -123,7 +123,7 @@ func getCaller() (method string) { } // if we got here, we failed to find the caller's context - return "UNKNOWN_CALLER" + return "" } // This function is not declared with a pointer value because otherwise @@ -133,7 +133,7 @@ func (entry Entry) log(level Level, msg string) { entry.Time = time.Now() entry.Level = level entry.Message = msg - if ReportCaller() { + if entry.Logger.ReportCaller { entry.Caller = getCaller() } if err := entry.Logger.Hooks.Fire(level, &entry); err != nil { diff --git a/exported.go b/exported.go index 356d4a9..3585f94 100644 --- a/exported.go +++ b/exported.go @@ -27,20 +27,14 @@ func SetFormatter(formatter Formatter) { std.Formatter = formatter } -// SetReportCaller sets whether to include the calling method as a field +// SetReportCaller sets whether the standard logger will include the calling +// method as a field. func SetReportCaller(include bool) { std.mu.Lock() defer std.mu.Unlock() std.ReportCaller = include } -// ReportCaller returns the 'include calling method' state -func ReportCaller() bool { - std.mu.Lock() - defer std.mu.Unlock() - return std.ReportCaller -} - // SetLevel sets the standard logger level. func SetLevel(level Level) { std.mu.Lock() diff --git a/formatter.go b/formatter.go index 9e94689..773b359 100644 --- a/formatter.go +++ b/formatter.go @@ -31,7 +31,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) { +func prefixFieldClashes(data Fields, reportCaller bool) { if t, ok := data["time"]; ok { data["fields.time"] = t } @@ -44,8 +44,8 @@ func prefixFieldClashes(data Fields) { data["fields.level"] = l } - // If Reportmethod is not set, 'method' will not conflict. - if ReportCaller() { + // If reportCaller is not set, 'method' will not conflict. + if reportCaller { if l, ok := data["method"]; ok { data["fields.method"] = l } diff --git a/json_formatter.go b/json_formatter.go index 2bb3a6a..46498da 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -52,7 +52,13 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data[k] = v } } - prefixFieldClashes(data) + + reportCaller := false + if entry.Logger != nil { + reportCaller = entry.Logger.ReportCaller + } + + prefixFieldClashes(data, reportCaller) timestampFormat := f.TimestampFormat if timestampFormat == "" { @@ -62,7 +68,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { 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 ReportCaller() { + if reportCaller { data[f.FieldMap.resolve(FieldKeyCaller)] = entry.Caller } serialized, err := json.Marshal(data) diff --git a/json_formatter_test.go b/json_formatter_test.go index ab52095..8235224 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -193,6 +193,7 @@ func TestFieldDoesNotClashWithCaller(t *testing.T) { func TestFieldClashWithCaller(t *testing.T) { SetReportCaller(true) formatter := &JSONFormatter{} + std.ReportCaller = true b, err := formatter.Format(WithField("method", "howdy pardner")) if err != nil { diff --git a/logrus_test.go b/logrus_test.go index ec31850..40cbd64 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -60,32 +60,30 @@ func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields ma // is added, and when it is unset it is not set or modified func TestReportCaller(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { - SetReportCaller(false) + log.ReportCaller = false log.Print("testNoCaller") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "testNoCaller") - assert.Equal(t, fields["level"], "info") - assert.Equal(t, fields["method"], nil) + assert.Equal(t, "testNoCaller", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, nil, fields["method"]) }) LogAndAssertJSON(t, func(log *Logger) { - SetReportCaller(true) + log.ReportCaller = true log.Print("testWithCaller") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "testWithCaller") - assert.Equal(t, fields["level"], "info") - assert.Equal(t, fields["method"], "testing.tRunner") + assert.Equal(t, "testWithCaller", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, "testing.tRunner", fields["method"]) }) - - SetReportCaller(false) // return to default value } 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"]) }) } @@ -93,8 +91,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"]) }) } @@ -102,8 +100,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"]) }) } @@ -111,7 +109,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"]) }) } @@ -119,7 +117,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"]) }) } @@ -127,7 +125,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"]) }) } @@ -135,7 +133,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"]) }) } @@ -143,7 +141,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"]) }) } @@ -151,7 +149,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"]) }) } @@ -189,7 +187,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"]) }) } @@ -197,8 +195,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"]) }) } @@ -206,7 +204,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"]) }) } @@ -214,8 +212,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 }) } @@ -259,8 +257,8 @@ 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") } @@ -269,10 +267,10 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { var buffer bytes.Buffer var fields Fields - SetReportCaller(true) logger := New() logger.Out = &buffer logger.Formatter = new(JSONFormatter) + logger.ReportCaller = true llog := logger.WithField("context", "eating raw fish") @@ -281,9 +279,9 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { err := json.Unmarshal(buffer.Bytes(), &fields) assert.NoError(t, err, "should have decoded first message") assert.Equal(t, len(fields), 5, "should have msg/time/level/method/context fields") - assert.Equal(t, fields["msg"], "looks delicious") - assert.Equal(t, fields["context"], "eating raw fish") - assert.Equal(t, fields["method"], "testing.tRunner") + assert.Equal(t, "looks delicious", fields["msg"]) + assert.Equal(t, "eating raw fish", fields["context"]) + assert.Equal(t, "testing.tRunner", fields["method"]) buffer.Reset() @@ -311,7 +309,7 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") assert.Equal(t, "testing.tRunner", fields["method"]) - SetReportCaller(false) // return to default value + logger.ReportCaller = false // return to default value } func TestConvertLevelToString(t *testing.T) { diff --git a/text_formatter.go b/text_formatter.go index b003451..91715f8 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -72,7 +72,12 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { b = &bytes.Buffer{} } - prefixFieldClashes(entry.Data) + reportCaller := false + if entry.Logger != nil { + reportCaller = entry.Logger.ReportCaller + } + + prefixFieldClashes(entry.Data, reportCaller) isColorTerminal := isTerminal && (runtime.GOOS != "windows") isColored := (f.ForceColors || isColorTerminal) && !f.DisableColors @@ -88,7 +93,7 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) } f.appendKeyValue(b, "level", entry.Level.String()) - if ReportCaller() { + if reportCaller { f.appendKeyValue(b, "method", entry.Caller) } if entry.Message != "" { @@ -119,7 +124,13 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin levelText := strings.ToUpper(entry.Level.String())[0:4] caller := "" - if ReportCaller() { + + reportCaller := false + if entry.Logger != nil { + reportCaller = entry.Logger.ReportCaller + } + + if reportCaller { caller = fmt.Sprintf(" %s()", entry.Caller) } From 65f3af38f74b4b71d4d75b72cc7e1d207bdd5cf2 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 30 Nov 2016 15:15:38 -0800 Subject: [PATCH 09/25] simplify hasCaller check --- entry.go | 6 ++++++ json_formatter.go | 9 ++------- json_formatter_test.go | 8 ++++---- text_formatter.go | 16 +++------------- 4 files changed, 15 insertions(+), 24 deletions(-) diff --git a/entry.go b/entry.go index 9e86687..d3b1aa9 100644 --- a/entry.go +++ b/entry.go @@ -126,6 +126,12 @@ func getCaller() (method string) { return "" } +func (entry Entry) HasCaller() (has bool) { + return entry.Logger != nil && + entry.Logger.ReportCaller && + entry.Caller != "" +} + // 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) { diff --git a/json_formatter.go b/json_formatter.go index 46498da..efb9a9a 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -53,12 +53,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { } } - reportCaller := false - if entry.Logger != nil { - reportCaller = entry.Logger.ReportCaller - } - - prefixFieldClashes(data, reportCaller) + prefixFieldClashes(data, entry.HasCaller()) timestampFormat := f.TimestampFormat if timestampFormat == "" { @@ -68,7 +63,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { 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 reportCaller { + if entry.HasCaller() { data[f.FieldMap.resolve(FieldKeyCaller)] = entry.Caller } serialized, err := json.Marshal(data) diff --git a/json_formatter_test.go b/json_formatter_test.go index 8235224..05cd51e 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -193,9 +193,9 @@ func TestFieldDoesNotClashWithCaller(t *testing.T) { func TestFieldClashWithCaller(t *testing.T) { SetReportCaller(true) formatter := &JSONFormatter{} - std.ReportCaller = true - - b, err := formatter.Format(WithField("method", "howdy pardner")) + e := WithField("method", "howdy pardner") + e.Caller = "somefunc" + b, err := formatter.Format(e) if err != nil { t.Fatal("Unable to format entry: ", err) } @@ -211,7 +211,7 @@ func TestFieldClashWithCaller(t *testing.T) { entry["fields.method"]) } - if entry["method"] != "" { // since we didn't actually log, it's set to the empty string + if entry["method"] != "somefunc" { t.Fatalf("method not set as expected when ReportCaller=true (got '%s')", entry["method"]) } diff --git a/text_formatter.go b/text_formatter.go index 91715f8..b0fa789 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -72,12 +72,7 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { b = &bytes.Buffer{} } - reportCaller := false - if entry.Logger != nil { - reportCaller = entry.Logger.ReportCaller - } - - prefixFieldClashes(entry.Data, reportCaller) + prefixFieldClashes(entry.Data, entry.HasCaller()) isColorTerminal := isTerminal && (runtime.GOOS != "windows") isColored := (f.ForceColors || isColorTerminal) && !f.DisableColors @@ -93,7 +88,7 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) } f.appendKeyValue(b, "level", entry.Level.String()) - if reportCaller { + if entry.HasCaller() { f.appendKeyValue(b, "method", entry.Caller) } if entry.Message != "" { @@ -125,12 +120,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin caller := "" - reportCaller := false - if entry.Logger != nil { - reportCaller = entry.Logger.ReportCaller - } - - if reportCaller { + if entry.HasCaller() { caller = fmt.Sprintf(" %s()", entry.Caller) } From 306956c385dcd90137fcf7c3cac8bbe938f6e768 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Thu, 1 Dec 2016 11:12:44 -0800 Subject: [PATCH 10/25] tweak timing tests to handle slower VMs and older GoLang --- logrus_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logrus_test.go b/logrus_test.go index 6765acf..58d9981 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -328,7 +328,7 @@ func logLoop(iterations int, reportCaller bool) { // Assertions for upper bounds to reporting overhead func TestCallerReportingOverhead(t *testing.T) { - iterations := 10000 + iterations := 5000 before := time.Now() logLoop(iterations, false) during := time.Now() From 802fba19a4dcbcabe24af1b67e0db5d5de175f04 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Fri, 2 Dec 2016 09:52:11 -0800 Subject: [PATCH 11/25] add note on caller-reporting overhead to README --- README.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/README.md b/README.md index 30402b6..083fcdc 100644 --- a/README.md +++ b/README.md @@ -75,6 +75,12 @@ This adds the caller as 'method' like so: time="2015-03-26T01:27:38-04:00" level=fatal method=arcticcreatures.migrate msg="a penguin swims by" animal=penguin ``` +Note that this does add measurable overhead - the cost will depend on the 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 +``` + + #### Example The simplest way to use Logrus is simply the package-level exported logger: From 2e7c40ede0b32845514d43c5d9f6e77d7eb8c548 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Fri, 2 Dec 2016 09:57:30 -0800 Subject: [PATCH 12/25] README formatting tweak --- README.md | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index 083fcdc..32d145b 100644 --- a/README.md +++ b/README.md @@ -68,17 +68,14 @@ This adds the caller as 'method' like so: ```json {"animal":"penguin","level":"fatal","method":"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=arcticcreatures.migrate msg="a penguin swims by" animal=penguin - -``` -Note that this does add measurable overhead - the cost will depend on the 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 ``` +Note that this does add measurable overhead - the cost will depend on the 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` #### Example From d8fd23467cdc8d7bdbb1ededd0cd859164aba652 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Fri, 2 Dec 2016 10:09:30 -0800 Subject: [PATCH 13/25] add syntax hilighting to new example blocks --- README.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 32d145b..bb71050 100644 --- a/README.md +++ b/README.md @@ -52,7 +52,7 @@ time="2015-03-26T01:27:38-04:00" level=fatal msg="The ice breaks!" err=&{0x20822 ``` To ensure this behaviour even if a TTY is attached, set your formatter as follows: -``` +```go log.SetFormatter(&log.TextFormatter{ DisableColors: true, FullTimestamp: true, @@ -60,7 +60,7 @@ To ensure this behaviour even if a TTY is attached, set your formatter as follow ``` 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: @@ -75,7 +75,7 @@ time="2015-03-26T01:27:38-04:00" level=fatal method=arcticcreatures.migrate msg= ``` Note that this does add measurable overhead - the cost will depend on the 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` +environment via benchmarks: ```go test -bench=.*CallerTracing``` #### Example From 88dd8df1f89474ff523f6fd18fcbe35a83534512 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Tue, 6 Dec 2016 12:53:21 -0800 Subject: [PATCH 14/25] responses to code review - field rename to be more properly generic - drop rewrite of main.main --- README.md | 5 ++++- entry.go | 6 +----- formatter.go | 12 +++++++----- json_formatter.go | 18 +++++++++--------- json_formatter_test.go | 20 ++++++++++---------- logrus_test.go | 36 ++++++++++++++++++------------------ text_formatter.go | 2 +- 7 files changed, 50 insertions(+), 49 deletions(-) diff --git a/README.md b/README.md index bb71050..329e769 100644 --- a/README.md +++ b/README.md @@ -75,7 +75,10 @@ time="2015-03-26T01:27:38-04:00" level=fatal method=arcticcreatures.migrate msg= ``` Note that this does add measurable overhead - the cost will depend on the 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``` +environment via benchmarks: +``` +go test -bench=.*CallerTracing +``` #### Example diff --git a/entry.go b/entry.go index a96f11d..50ca795 100644 --- a/entry.go +++ b/entry.go @@ -138,11 +138,7 @@ func getCaller() (method string) { // If the caller isn't part of this package, we're done if pkg != logrusPackage { - if fullFuncName == "main.main" { - return "main" - } else { - return fullFuncName - } + return fullFuncName } } diff --git a/formatter.go b/formatter.go index 773b359..ae319c3 100644 --- a/formatter.go +++ b/formatter.go @@ -1,6 +1,8 @@ package logrus -import "time" +import ( + "time" +) // DefaultTimestampFormat is YYYY-mm-DDTHH:MM:SS-TZ const DefaultTimestampFormat = time.RFC3339 @@ -19,7 +21,7 @@ type Formatter interface { Format(*Entry) ([]byte, error) } -// This is to not silently overwrite `time`, `msg`, `method` 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") @@ -44,10 +46,10 @@ func prefixFieldClashes(data Fields, reportCaller bool) { data["fields.level"] = l } - // If reportCaller is not set, 'method' will not conflict. + // If reportCaller is not set, 'func' will not conflict. if reportCaller { - if l, ok := data["method"]; ok { - data["fields.method"] = l + if l, ok := data["func"]; ok { + data["fields.func"] = l } } } diff --git a/json_formatter.go b/json_formatter.go index 110b91d..8bdac89 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -9,10 +9,10 @@ type fieldKey string type FieldMap map[fieldKey]string const ( - FieldKeyMsg = "msg" - FieldKeyLevel = "level" - FieldKeyTime = "time" - FieldKeyCaller = "method" + FieldKeyMsg = "msg" + FieldKeyLevel = "level" + FieldKeyTime = "time" + FieldKeyFunc = "func" ) func (f FieldMap) resolve(key fieldKey) string { @@ -34,10 +34,10 @@ type JSONFormatter struct { // As an example: // formatter := &JSONFormatter{ // FieldMap: FieldMap{ - // FieldKeyTime: "@timestamp", - // FieldKeyLevel: "@level", - // FieldKeyMsg: "@message", - // FieldKeyCaller: "@caller", + // FieldKeyTime: "@timestamp", + // FieldKeyLevel: "@level", + // FieldKeyMsg: "@message", + // FieldKeyFunc: "@caller", // }, // } FieldMap FieldMap @@ -69,7 +69,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data[f.FieldMap.resolve(FieldKeyMsg)] = entry.Message data[f.FieldMap.resolve(FieldKeyLevel)] = entry.Level.String() if entry.HasCaller() { - data[f.FieldMap.resolve(FieldKeyCaller)] = entry.Caller + data[f.FieldMap.resolve(FieldKeyFunc)] = entry.Caller } serialized, err := json.Marshal(data) if err != nil { diff --git a/json_formatter_test.go b/json_formatter_test.go index 4a7e5e7..84c7882 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -174,7 +174,7 @@ func TestFieldDoesNotClashWithCaller(t *testing.T) { SetReportCaller(false) formatter := &JSONFormatter{} - b, err := formatter.Format(WithField("method", "howdy pardner")) + b, err := formatter.Format(WithField("func", "howdy pardner")) if err != nil { t.Fatal("Unable to format entry: ", err) } @@ -185,15 +185,15 @@ func TestFieldDoesNotClashWithCaller(t *testing.T) { t.Fatal("Unable to unmarshal formatted entry: ", err) } - if entry["method"] != "howdy pardner" { - t.Fatal("method field replaced when ReportCaller=false") + if entry["func"] != "howdy pardner" { + t.Fatal("func field replaced when ReportCaller=false") } } func TestFieldClashWithCaller(t *testing.T) { SetReportCaller(true) formatter := &JSONFormatter{} - e := WithField("method", "howdy pardner") + e := WithField("func", "howdy pardner") e.Caller = "somefunc" b, err := formatter.Format(e) if err != nil { @@ -206,14 +206,14 @@ func TestFieldClashWithCaller(t *testing.T) { t.Fatal("Unable to unmarshal formatted entry: ", err) } - if entry["fields.method"] != "howdy pardner" { - t.Fatalf("fields.method not set to original method field when ReportCaller=true (got '%s')", - entry["fields.method"]) + 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["method"] != "somefunc" { - t.Fatalf("method not set as expected when ReportCaller=true (got '%s')", - entry["method"]) + if entry["func"] != "somefunc" { + t.Fatalf("func not set as expected when ReportCaller=true (got '%s')", + entry["func"]) } SetReportCaller(false) // return to default value diff --git a/logrus_test.go b/logrus_test.go index 58d9981..7b5c2c4 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -57,7 +57,7 @@ func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields ma assertions(fields) } -// TestReportCaller verifies that when ReportCaller is set, the 'method' field +// TestReportCaller verifies that when ReportCaller is set, the 'func' field // is added, and when it is unset it is not set or modified func TestReportCaller(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { @@ -66,7 +66,7 @@ func TestReportCaller(t *testing.T) { }, func(fields Fields) { assert.Equal(t, "testNoCaller", fields["msg"]) assert.Equal(t, "info", fields["level"]) - assert.Equal(t, nil, fields["method"]) + assert.Equal(t, nil, fields["func"]) }) LogAndAssertJSON(t, func(log *Logger) { @@ -75,7 +75,7 @@ func TestReportCaller(t *testing.T) { }, func(fields Fields) { assert.Equal(t, "testWithCaller", fields["msg"]) assert.Equal(t, "info", fields["level"]) - assert.Equal(t, "testing.tRunner", fields["method"]) + assert.Equal(t, "testing.tRunner", fields["func"]) }) } @@ -279,36 +279,36 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { err := json.Unmarshal(buffer.Bytes(), &fields) assert.NoError(t, err, "should have decoded first message") - assert.Equal(t, len(fields), 5, "should have msg/time/level/method/context fields") + assert.Equal(t, len(fields), 5, "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, "testing.tRunner", fields["method"]) + assert.Equal(t, "testing.tRunner", fields["func"]) buffer.Reset() logger.WithFields(Fields{ - "foo": "a", + "Clyde": "Stubblefield", }).WithFields(Fields{ - "bar": "b", + "Jab'o": "Starks", }).WithFields(Fields{ - "baz": "c", + "uri": "https://www.youtube.com/watch?v=V5DTznu-9v0", }).WithFields(Fields{ - "method": "man", + "func": "y drummer", }).WithFields(Fields{ - "clan": "Wu Tang", - }).Print("omg it is!") + "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, 10, len(fields), "should have all builtin fields plus foo,bar,baz,...") - assert.Equal(t, "omg it is!", fields["msg"]) - assert.Equal(t, "a", fields["foo"]) - assert.Equal(t, "b", fields["bar"]) - assert.Equal(t, "c", fields["baz"]) - assert.Equal(t, "man", fields["fields.method"]) - assert.Equal(t, "Wu Tang", fields["clan"]) + 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, "testing.tRunner", fields["method"]) + assert.Equal(t, "testing.tRunner", fields["func"]) logger.ReportCaller = false // return to default value } diff --git a/text_formatter.go b/text_formatter.go index b0fa789..b4abd50 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -89,7 +89,7 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { } f.appendKeyValue(b, "level", entry.Level.String()) if entry.HasCaller() { - f.appendKeyValue(b, "method", entry.Caller) + f.appendKeyValue(b, "func", entry.Caller) } if entry.Message != "" { f.appendKeyValue(b, "msg", entry.Message) From bc6d984670dab2f0fca29bd13aebb15969766fd2 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Fri, 3 Feb 2017 15:08:53 -0800 Subject: [PATCH 15/25] add caller logic to DisableTimestamp case --- README.md | 2 +- text_formatter.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index b6e2afd..720f85a 100644 --- a/README.md +++ b/README.md @@ -73,7 +73,7 @@ This adds the caller as 'method' like so: ```text time="2015-03-26T01:27:38-04:00" level=fatal method=arcticcreatures.migrate msg="a penguin swims by" animal=penguin ``` -Note that this does add measurable overhead - the cost will depend on the of Go, but is +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: ``` diff --git a/text_formatter.go b/text_formatter.go index 6f9c72d..7c63ac3 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -121,7 +121,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin } 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]%s %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), caller, entry.Message) } else { From 3cb9e18ef925540b009fdb6f1289ae64a3be12d7 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 2 Aug 2017 17:21:18 -0700 Subject: [PATCH 16/25] test updates - add tests for callers accessed directly or via function pointer (results are unchanged) - undo unwanted capitalization/export in previous commit --- entry.go | 8 ++++---- formatter.go | 4 ++-- logrus_test.go | 49 ++++++++++++++++++++++++++++++++++++++++++++++++- 3 files changed, 54 insertions(+), 7 deletions(-) diff --git a/entry.go b/entry.go index 11f79c9..1d0a603 100644 --- a/entry.go +++ b/entry.go @@ -13,7 +13,7 @@ import ( var bufferPool *sync.Pool // qualified package name, cached at first use -var logrusPackage string +var LogrusPackage string // Positions in the call stack when tracing to report the calling method var minimumCallerDepth int @@ -126,8 +126,8 @@ func getCaller() (method string) { depth := runtime.Callers(minimumCallerDepth, pcs) // cache this package's fully-qualified name - if logrusPackage == "" { - logrusPackage = getPackageName(runtime.FuncForPC(pcs[0]).Name()) + if LogrusPackage == "" { + LogrusPackage = getPackageName(runtime.FuncForPC(pcs[0]).Name()) // now that we have the cache, we can skip a minimum count of known-logrus functions minimumCallerDepth = knownLogrusFrames @@ -138,7 +138,7 @@ func getCaller() (method string) { pkg := getPackageName(fullFuncName) // If the caller isn't part of this package, we're done - if pkg != logrusPackage { + if pkg != LogrusPackage { return fullFuncName } } diff --git a/formatter.go b/formatter.go index dc6631d..ba7b509 100644 --- a/formatter.go +++ b/formatter.go @@ -2,8 +2,8 @@ package logrus import "time" -// DefaultTimestampFormat is YYYY-mm-DDTHH:MM:SS-TZ -const DefaultTimestampFormat = time.RFC3339 +// defaultTimestampFormat is YYYY-mm-DDTHH:MM:SS-TZ +const defaultTimestampFormat = time.RFC3339 // The Formatter interface is used to implement a custom Formatter. It takes an // `Entry`. It exposes all the fields, including the default ones: diff --git a/logrus_test.go b/logrus_test.go index e724cc8..66c863d 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -59,7 +59,9 @@ func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields ma // TestReportCaller verifies that when ReportCaller is set, the 'func' field // is added, and when it is unset it is not set or modified -func TestReportCaller(t *testing.T) { +// 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") @@ -79,6 +81,51 @@ func TestReportCaller(t *testing.T) { }) } +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 + + // override the filter to allow reporting of functions within the logrus package + LogrusPackage = "bogusForTesting" + + entry := logger.WithFields(Fields{ + "foo": "bar", + }) + + entry.Info(message) + + err := json.Unmarshal(buffer.Bytes(), &fields) + assert.Nil(t, err) + + // now clear the override so as not to mess with other usage + LogrusPackage = "" + return fields +} + +// TestReportCallerHelperDirect - verify reference when logging from a regular function +func TestReportCallerHelperDirect(t *testing.T) { + fields := logSomething(t, "direct") + + assert.Equal(t, "direct", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, "github.com/dclendenan/logrus.logSomething", fields["func"]) +} + +// TestReportCallerHelperDirect - verify reference when logging from a function called via pointer +func TestReportCallerHelperViaPointer(t *testing.T) { + fptr := logSomething + fields := fptr(t, "via pointer") + + assert.Equal(t, "via pointer", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, "github.com/dclendenan/logrus.logSomething", fields["func"]) +} + func TestPrint(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Print("test") From b1db1b9c673ac4bc6e3d7fc64b7fb11f6ec187ca Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 2 Aug 2017 17:28:13 -0700 Subject: [PATCH 17/25] regex assertion rather than literal, for github path --- logrus_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/logrus_test.go b/logrus_test.go index 66c863d..3fc68c9 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -113,7 +113,7 @@ func TestReportCallerHelperDirect(t *testing.T) { assert.Equal(t, "direct", fields["msg"]) assert.Equal(t, "info", fields["level"]) - assert.Equal(t, "github.com/dclendenan/logrus.logSomething", fields["func"]) + assert.Regexp(t, "github.com/.*/logrus.logSomething", fields["func"]) } // TestReportCallerHelperDirect - verify reference when logging from a function called via pointer @@ -123,7 +123,7 @@ func TestReportCallerHelperViaPointer(t *testing.T) { assert.Equal(t, "via pointer", fields["msg"]) assert.Equal(t, "info", fields["level"]) - assert.Equal(t, "github.com/dclendenan/logrus.logSomething", fields["func"]) + assert.Regexp(t, "github.com/.*/logrus.logSomething", fields["func"]) } func TestPrint(t *testing.T) { From 9ce1c9e3b52084b3cb71a1fd9a5791542e6674c1 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 2 Aug 2017 17:33:13 -0700 Subject: [PATCH 18/25] add github path to log message in readme --- README.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index 3c22360..7a78d98 100644 --- a/README.md +++ b/README.md @@ -73,12 +73,12 @@ log.SetReportCaller(true) This adds the caller as 'method' like so: ```json -{"animal":"penguin","level":"fatal","method":"arcticcreatures.migrate","msg":"a penguin swims by", +{"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=arcticcreatures.migrate msg="a penguin swims by" animal=penguin +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 From e3d17767d1dbd87b98f0a835a618bc8e26daaac8 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Wed, 2 Aug 2017 17:35:14 -0700 Subject: [PATCH 19/25] MD formatting --- README.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/README.md b/README.md index 7a78d98..df7c0da 100644 --- a/README.md +++ b/README.md @@ -66,6 +66,8 @@ To ensure this behaviour even if a TTY is attached, set your formatter as follow }) ``` +#### Logging Method Name + If you wish to add the calling method as a field, instruct the logger via: ```go log.SetReportCaller(true) From 5fcd19eae6dad060b6bf73cde67273d0f2eed02f Mon Sep 17 00:00:00 2001 From: David Bariod Date: Sat, 27 Oct 2018 15:19:06 +0200 Subject: [PATCH 20/25] add a SetReportCaller on Logger object --- exported.go | 4 +--- logger.go | 6 ++++++ 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/exported.go b/exported.go index 979582d..7342613 100644 --- a/exported.go +++ b/exported.go @@ -27,9 +27,7 @@ func SetFormatter(formatter Formatter) { // SetReportCaller sets whether the standard logger will include the calling // method as a field. func SetReportCaller(include bool) { - std.mu.Lock() - defer std.mu.Unlock() - std.ReportCaller = include + std.SetReportCaller(include) } // SetLevel sets the standard logger level. diff --git a/logger.go b/logger.go index 68fca98..5ceca0e 100644 --- a/logger.go +++ b/logger.go @@ -399,6 +399,12 @@ func (logger *Logger) SetOutput(output io.Writer) { 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() From 975c406ddb02ea083d859e81a86dcd8a3854217a Mon Sep 17 00:00:00 2001 From: David Bariod Date: Sat, 27 Oct 2018 15:21:30 +0200 Subject: [PATCH 21/25] Use a sync.Once to init the reportCaller data --- entry.go | 30 +++++++++++++++++++----------- logrus_test.go | 4 ++-- 2 files changed, 21 insertions(+), 13 deletions(-) diff --git a/entry.go b/entry.go index df37550..5f40c58 100644 --- a/entry.go +++ b/entry.go @@ -11,16 +11,23 @@ import ( "time" ) -var bufferPool *sync.Pool +var ( + bufferPool *sync.Pool -// qualified package name, cached at first use -var LogrusPackage string + // qualified package name, cached at first use + logrusPackage string -// Positions in the call stack when tracing to report the calling method -var minimumCallerDepth int + // Positions in the call stack when tracing to report the calling method + minimumCallerDepth int -const maximumCallerDepth int = 25 -const knownLogrusFrames int = 4 + // Used for caller information initialisation + callerInitOnce sync.Once +) + +const ( + maximumCallerDepth int = 25 + knownLogrusFrames int = 4 +) func init() { bufferPool = &sync.Pool{ @@ -143,19 +150,20 @@ func getCaller() (method string) { depth := runtime.Callers(minimumCallerDepth, pcs) // cache this package's fully-qualified name - if LogrusPackage == "" { - LogrusPackage = getPackageName(runtime.FuncForPC(pcs[0]).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 i := 0; i < depth; i++ { fullFuncName := runtime.FuncForPC(pcs[i]).Name() pkg := getPackageName(fullFuncName) // If the caller isn't part of this package, we're done - if pkg != LogrusPackage { + if pkg != logrusPackage { return fullFuncName } } diff --git a/logrus_test.go b/logrus_test.go index d829369..2fe3653 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -92,7 +92,7 @@ func logSomething(t *testing.T, message string) Fields { logger.ReportCaller = true // override the filter to allow reporting of functions within the logrus package - LogrusPackage = "bogusForTesting" + logrusPackage = "bogusForTesting" entry := logger.WithFields(Fields{ "foo": "bar", @@ -104,7 +104,7 @@ func logSomething(t *testing.T, message string) Fields { assert.Nil(t, err) // now clear the override so as not to mess with other usage - LogrusPackage = "" + logrusPackage = "" return fields } From ec57031db11c2a7783cbc010a6c2c9ab10a8e039 Mon Sep 17 00:00:00 2001 From: David Bariod Date: Sun, 28 Oct 2018 10:12:11 +0100 Subject: [PATCH 22/25] store a runtime.Frame in Entry instead of the caller function name --- entry.go | 16 ++++++++-------- json_formatter.go | 2 +- json_formatter_test.go | 7 ++++--- text_formatter.go | 2 +- 4 files changed, 14 insertions(+), 13 deletions(-) diff --git a/entry.go b/entry.go index 5f40c58..cc85d3a 100644 --- a/entry.go +++ b/entry.go @@ -61,7 +61,7 @@ type Entry struct { Level Level // Calling method, with package name - Caller string + Caller *runtime.Frame // Message passed to Trace, Debug, Info, Warn, Error, Fatal or Panic Message string @@ -144,10 +144,11 @@ func getPackageName(f string) string { } // getCaller retrieves the name of the first non-logrus calling function -func getCaller() (method string) { +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() { @@ -158,24 +159,23 @@ func getCaller() (method string) { minimumCallerDepth = knownLogrusFrames }) - for i := 0; i < depth; i++ { - fullFuncName := runtime.FuncForPC(pcs[i]).Name() - pkg := getPackageName(fullFuncName) + 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 fullFuncName + return &f } } // if we got here, we failed to find the caller's context - return "" + return nil } func (entry Entry) HasCaller() (has bool) { return entry.Logger != nil && entry.Logger.ReportCaller && - entry.Caller != "" + entry.Caller != nil } // This function is not declared with a pointer value because otherwise diff --git a/json_formatter.go b/json_formatter.go index bdb569e..f5d45bb 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -82,7 +82,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { 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 + data[f.FieldMap.resolve(FieldKeyFunc)] = entry.Caller.Function } var b *bytes.Buffer diff --git a/json_formatter_test.go b/json_formatter_test.go index 13fbf31..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 @@ -291,7 +292,7 @@ func TestFieldClashWithCaller(t *testing.T) { SetReportCaller(true) formatter := &JSONFormatter{} e := WithField("func", "howdy pardner") - e.Caller = "somefunc" + e.Caller = &runtime.Frame{Function: "somefunc"} b, err := formatter.Format(e) if err != nil { t.Fatal("Unable to format entry: ", err) diff --git a/text_formatter.go b/text_formatter.go index 409edc0..354387c 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -208,7 +208,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin caller := "" if entry.HasCaller() { - caller = fmt.Sprintf(" %s()", entry.Caller) + caller = fmt.Sprintf(" %s()", entry.Caller.Function) } if f.DisableTimestamp { From fa01b530978c5b5bc0eade9c6198f409fd5c6859 Mon Sep 17 00:00:00 2001 From: David Bariod Date: Sun, 28 Oct 2018 14:07:57 +0100 Subject: [PATCH 23/25] move test functions and test utils functions in their own package --- hook_test.go | 5 ++- internal/testutils/testutils.go | 58 ++++++++++++++++++++++++ logrus_test.go | 79 +++++++-------------------------- 3 files changed, 79 insertions(+), 63 deletions(-) create mode 100644 internal/testutils/testutils.go diff --git a/hook_test.go b/hook_test.go index 7196e99..b967593 100644 --- a/hook_test.go +++ b/hook_test.go @@ -1,4 +1,4 @@ -package logrus +package logrus_test import ( "bytes" @@ -8,6 +8,9 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + + . "github.com/sirupsen/logrus" + . "github.com/sirupsen/logrus/internal/testutils" ) type TestHook struct { 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/logrus_test.go b/logrus_test.go index 2fe3653..3b1d256 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -1,63 +1,20 @@ -package logrus +package logrus_test import ( "bytes" "encoding/json" "io/ioutil" - "strconv" - "strings" "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)) { - var buffer bytes.Buffer - var fields Fields - - logger := New() - logger.Out = &buffer - logger.Formatter = new(JSONFormatter) - - log(logger) - - err := json.Unmarshal(buffer.Bytes(), &fields) - assert.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) - assert.NoError(t, err) - } - fields[key] = val - } - assertions(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 @@ -78,7 +35,8 @@ func TestReportCallerWhenConfigured(t *testing.T) { }, func(fields Fields) { assert.Equal(t, "testWithCaller", fields["msg"]) assert.Equal(t, "info", fields["level"]) - assert.Equal(t, "testing.tRunner", fields["func"]) + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestReportCallerWhenConfigured.func3", fields["func"]) }) } @@ -91,9 +49,6 @@ func logSomething(t *testing.T, message string) Fields { logger.Formatter = new(JSONFormatter) logger.ReportCaller = true - // override the filter to allow reporting of functions within the logrus package - logrusPackage = "bogusForTesting" - entry := logger.WithFields(Fields{ "foo": "bar", }) @@ -103,8 +58,6 @@ func logSomething(t *testing.T, message string) Fields { err := json.Unmarshal(buffer.Bytes(), &fields) assert.Nil(t, err) - // now clear the override so as not to mess with other usage - logrusPackage = "" return fields } @@ -114,7 +67,7 @@ func TestReportCallerHelperDirect(t *testing.T) { assert.Equal(t, "direct", fields["msg"]) assert.Equal(t, "info", fields["level"]) - assert.Regexp(t, "github.com/.*/logrus.logSomething", fields["func"]) + assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"]) } // TestReportCallerHelperDirect - verify reference when logging from a function called via pointer @@ -124,7 +77,7 @@ func TestReportCallerHelperViaPointer(t *testing.T) { assert.Equal(t, "via pointer", fields["msg"]) assert.Equal(t, "info", fields["level"]) - assert.Regexp(t, "github.com/.*/logrus.logSomething", fields["func"]) + assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"]) } func TestPrint(t *testing.T) { @@ -286,7 +239,7 @@ func TestWithTimeShouldOverrideTime(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithTime(now).Info("foobar") }, func(fields Fields) { - assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat)) + assert.Equal(t, fields["time"], now.Format(time.RFC3339)) }) } @@ -296,7 +249,7 @@ func TestWithTimeShouldNotOverrideFields(t *testing.T) { 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["time"], now.Format(time.RFC3339)) assert.Equal(t, fields["herp"], "derp") }) } @@ -307,7 +260,7 @@ func TestWithFieldShouldNotOverrideTime(t *testing.T) { 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["time"], now.Format(time.RFC3339)) assert.Equal(t, fields["herp"], "derp") }) } @@ -385,11 +338,12 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { llog.Info("looks delicious") err := json.Unmarshal(buffer.Bytes(), &fields) - assert.NoError(t, err, "should have decoded first message") + require.NoError(t, err, "should have decoded first message") assert.Equal(t, len(fields), 5, "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, "testing.tRunner", fields["func"]) + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) buffer.Reset() @@ -415,7 +369,8 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { 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, "testing.tRunner", fields["func"]) + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) logger.ReportCaller = false // return to default value } From d2654b752f1ef4f33cce0b405c0f118bf1b69bdd Mon Sep 17 00:00:00 2001 From: David Bariod Date: Sun, 28 Oct 2018 17:39:39 +0100 Subject: [PATCH 24/25] add file and line number in output when report caller is enabled --- formatter.go | 5 +++++ json_formatter.go | 1 + logrus_test.go | 10 ++++++++-- text_formatter.go | 10 ++++++++-- 4 files changed, 22 insertions(+), 4 deletions(-) diff --git a/formatter.go b/formatter.go index db37848..4088837 100644 --- a/formatter.go +++ b/formatter.go @@ -10,6 +10,7 @@ const ( FieldKeyTime = "time" FieldKeyLogrusError = "logrus_error" FieldKeyFunc = "func" + FieldKeyFile = "file" ) // The Formatter interface is used to implement a custom Formatter. It takes an @@ -69,5 +70,9 @@ func prefixFieldClashes(data Fields, fieldMap FieldMap, reportCaller bool) { 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/json_formatter.go b/json_formatter.go index f5d45bb..2605753 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -83,6 +83,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { 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) } var b *bytes.Buffer diff --git a/logrus_test.go b/logrus_test.go index 3b1d256..27cddaf 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -4,6 +4,7 @@ import ( "bytes" "encoding/json" "io/ioutil" + "os" "sync" "testing" "time" @@ -339,11 +340,14 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { err := json.Unmarshal(buffer.Bytes(), &fields) require.NoError(t, err, "should have decoded first message") - assert.Equal(t, len(fields), 5, "should have msg/time/level/func/context fields") + 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, cwd+"/logrus_test.go:339", fields["file"]) buffer.Reset() @@ -361,7 +365,7 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { err = json.Unmarshal(buffer.Bytes(), &fields) assert.NoError(t, err, "should have decoded second message") - assert.Equal(t, 10, len(fields), "should have all builtin fields plus foo,bar,baz,...") + 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"]) @@ -371,6 +375,8 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { 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, cwd+"/logrus_test.go:364", fields["file"]) logger.ReportCaller = false // return to default value } diff --git a/text_formatter.go b/text_formatter.go index 354387c..c5f9ca3 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -126,7 +126,8 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLogrusError)) } if entry.HasCaller() { - fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyFunc)) + fixedKeys = append(fixedKeys, + f.FieldMap.resolve(FieldKeyFunc), f.FieldMap.resolve(FieldKeyFile)) } if !f.DisableSorting { @@ -172,6 +173,10 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { value = entry.Message case f.FieldMap.resolve(FieldKeyLogrusError): value = entry.err + case f.FieldMap.resolve(FieldKeyFunc): + value = entry.Caller.Function + case f.FieldMap.resolve(FieldKeyFile): + value = fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) default: value = entry.Data[key] } @@ -208,7 +213,8 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin caller := "" if entry.HasCaller() { - caller = fmt.Sprintf(" %s()", entry.Caller.Function) + caller = fmt.Sprintf("%s:%d %s()", + entry.Caller.File, entry.Caller.Line, entry.Caller.Function) } if f.DisableTimestamp { From 5a78c38d0e21bb6cfcc02703f25b9232b0312ccd Mon Sep 17 00:00:00 2001 From: David Bariod Date: Sun, 28 Oct 2018 18:12:32 +0100 Subject: [PATCH 25/25] make file name comparison os independant --- logrus_test.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/logrus_test.go b/logrus_test.go index 27cddaf..7c99825 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -5,6 +5,7 @@ import ( "encoding/json" "io/ioutil" "os" + "path/filepath" "sync" "testing" "time" @@ -347,7 +348,7 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) cwd, err := os.Getwd() require.NoError(t, err) - assert.Equal(t, cwd+"/logrus_test.go:339", fields["file"]) + assert.Equal(t, filepath.ToSlash(cwd+"/logrus_test.go:340"), filepath.ToSlash(fields["file"].(string))) buffer.Reset() @@ -376,7 +377,7 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) { assert.Equal(t, "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) require.NoError(t, err) - assert.Equal(t, cwd+"/logrus_test.go:364", fields["file"]) + assert.Equal(t, filepath.ToSlash(cwd+"/logrus_test.go:365"), filepath.ToSlash(fields["file"].(string))) logger.ReportCaller = false // return to default value }