From bc6d984670dab2f0fca29bd13aebb15969766fd2 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Fri, 3 Feb 2017 15:08:53 -0800 Subject: [PATCH 1/5] 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 2/5] 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 3/5] 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 4/5] 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 5/5] 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)