merge upstream, add tests, full method context

- added benchmarks, and assertions for timeliness
- replaced regex usage in package-name handling with a straight
  comparison to a cached value
- log the fullly-qualified method name, to remove ambiguity
    eg: github.com/fflintstone/yabba.dabba.doo
- clean up possibly-unsafe assumptions about using the standard logger,
  remove global lookup function to enforce safe usage

README.md

@@ -1,4 +1,4 @@
-# Logrus <img src="http://i.imgur.com/hTeVwmJ.png" width="40" height="40" alt=":walrus:" class="emoji" title=":walrus:"/>&nbsp;[![Build Status](https://travis-ci.org/Sirupsen/logrus.svg?branch=master)](https://travis-ci.org/Sirupsen/logrus)&nbsp;[![GoDoc](https://godoc.org/github.com/Sirupsen/logrus?status.svg)](https://godoc.org/github.com/Sirupsen/logrus)
+# Logrus <img src="http://i.imgur.com/hTeVwmJ.png" width="40" height="40" alt=":walrus:" class="emoji" title=":walrus:"/>&nbsp;[![Build Status](https://travis-ci.org/sirupsen/logrus.svg?branch=master)](https://travis-ci.org/sirupsen/logrus)&nbsp;[![GoDoc](https://godoc.org/github.com/sirupsen/logrus?status.svg)](https://godoc.org/github.com/sirupsen/logrus)
 
 Logrus is a structured logger for Go (golang), completely API compatible with
 the standard library logger. [Godoc][godoc]. **Please note the Logrus API is not
@@ -77,7 +77,7 @@ The simplest way to use Logrus is simply the package-level exported logger:
 package main
 
 import (
-  log "github.com/Sirupsen/logrus"
+  log "github.com/sirupsen/logrus"
 )
 
 func main() {
@@ -88,7 +88,7 @@ func main() {
 ```
 
 Note that it's completely api-compatible with the stdlib logger, so you can
-replace your `log` imports everywhere with `log "github.com/Sirupsen/logrus"`
+replace your `log` imports everywhere with `log "github.com/sirupsen/logrus"`
 and you'll now have the flexibility of Logrus. You can customize it all you
 want:
 
@@ -97,7 +97,7 @@ package main
 
 import (
   "os"
-  log "github.com/Sirupsen/logrus"
+  log "github.com/sirupsen/logrus"
 )
 
 func init() {
@@ -146,7 +146,7 @@ application, you can also create an instance of the `logrus` Logger:
 package main
 
 import (
-  "github.com/Sirupsen/logrus"
+  "github.com/sirupsen/logrus"
 )
 
 // Create a new instance of the logger. You can have any number of instances.
@@ -199,9 +199,9 @@ Logrus comes with [built-in hooks](hooks/). Add those, or your custom hook, in
 
 ```go
 import (
-  log "github.com/Sirupsen/logrus"
+  log "github.com/sirupsen/logrus"
   "gopkg.in/gemnasium/logrus-airbrake-hook.v2" // the package is named "aibrake"
-  logrus_syslog "github.com/Sirupsen/logrus/hooks/syslog"
+  logrus_syslog "github.com/sirupsen/logrus/hooks/syslog"
   "log/syslog"
 )
 
@@ -226,7 +226,7 @@ Note: Syslog hook also support connecting to local syslog (Ex. "/dev/log" or "/v
 | [Airbrake](https://github.com/gemnasium/logrus-airbrake-hook) | Send errors to the Airbrake API V3. Uses the official [`gobrake`](https://github.com/airbrake/gobrake) behind the scenes. |
 | [Airbrake "legacy"](https://github.com/gemnasium/logrus-airbrake-legacy-hook) | Send errors to an exception tracking service compatible with the Airbrake API V2. Uses [`airbrake-go`](https://github.com/tobi/airbrake-go) behind the scenes. |
 | [Papertrail](https://github.com/polds/logrus-papertrail-hook) | Send errors to the [Papertrail](https://papertrailapp.com) hosted logging service via UDP. |
-| [Syslog](https://github.com/Sirupsen/logrus/blob/master/hooks/syslog/syslog.go) | Send errors to remote syslog server. Uses standard library `log/syslog` behind the scenes. |
+| [Syslog](https://github.com/sirupsen/logrus/blob/master/hooks/syslog/syslog.go) | Send errors to remote syslog server. Uses standard library `log/syslog` behind the scenes. |
 | [Bugsnag](https://github.com/Shopify/logrus-bugsnag/blob/master/bugsnag.go) | Send errors to the Bugsnag exception tracking service. |
 | [Sentry](https://github.com/evalphobia/logrus_sentry) | Send errors to the Sentry error logging and aggregation service. |
 | [Hiprus](https://github.com/nubo/hiprus) | Send errors to a channel in hipchat. |
@@ -306,7 +306,7 @@ could do:
 
 ```go
 import (
-  log "github.com/Sirupsen/logrus"
+  log "github.com/sirupsen/logrus"
 )
 
 init() {
@@ -431,7 +431,7 @@ logrus.RegisterExitHandler(handler)
 ...
 ```
 
-#### Thread safty
+#### Thread safety
 
 By default Logger is protected by mutex for concurrent writes, this mutex is invoked when calling hooks and writing logs.
 If you are sure such locking is not needed, you can call logger.SetNoLock() to disable the locking.

doc.go

@@ -7,7 +7,7 @@ The simplest way to use Logrus is simply the package-level exported logger:
   package main
 
   import (
-    log "github.com/Sirupsen/logrus"
+    log "github.com/sirupsen/logrus"
   )
 
   func main() {
@@ -21,6 +21,6 @@ The simplest way to use Logrus is simply the package-level exported logger:
 Output:
   time="2015-09-07T08:48:33Z" level=info msg="A walrus appears" animal=walrus number=1 size=10
 
-For a full guide visit https://github.com/Sirupsen/logrus
+For a full guide visit https://github.com/sirupsen/logrus
 */
 package logrus

entry.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"fmt"
 	"os"
-	"regexp"
 	"runtime"
 	"strings"
 	"sync"
@@ -13,8 +12,14 @@ import (
 
 var bufferPool *sync.Pool
 
-// regex for validation is external, to reduce compilation overhead
-var matchesLogrus *regexp.Regexp
+// qualified package name, cached at first use
+var logrusPackage string
+
+// Positions in the call stack when tracing to report the calling method
+var minimumCallerDepth int
+
+const maximumCallerDepth int = 25
+const knownLogrusFrames int = 4
 
 func init() {
 	bufferPool = &sync.Pool{
@@ -23,7 +28,8 @@ func init() {
 		},
 	}
 
-	matchesLogrus, _ = regexp.Compile("logrus.*")
+	// start at the bottom of the stack before the package-name cache is primed
+	minimumCallerDepth = 1
 }
 
 // Defines the key when adding errors using WithError.
@@ -96,24 +102,42 @@ func (entry *Entry) WithFields(fields Fields) *Entry {
 	return &Entry{Logger: entry.Logger, Data: data}
 }
 
+// getPackageName reduces a fully qualified function name to the package name
+// There really ought to be to be a better way...
+func getPackageName(f string) string {
+	for {
+		lastPeriod := strings.LastIndex(f, ".")
+		lastSlash := strings.LastIndex(f, "/")
+		if lastPeriod > lastSlash {
+			f = f[:lastPeriod]
+		} else {
+			break
+		}
+	}
+
+	return f
+}
+
 // getCaller retrieves the name of the first non-logrus calling function
 func getCaller() (method string) {
-	// Restrict the lookback to 25 frames - if it's further than that, report UNKNOWN
-	pcs := make([]uintptr, 25)
+	// Restrict the lookback frames to avoid runaway lookups
+	pcs := make([]uintptr, maximumCallerDepth)
+	depth := runtime.Callers(minimumCallerDepth, pcs)
+
+	// cache this package's fully-qualified 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
+	}
 
-	// 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:]
-		}
+		pkg := getPackageName(fullFuncName)
 
-		matched := matchesLogrus.MatchString(fullFuncName)
-
-		// If the caller isn't part of logrus, we're done
-		if !matched {
+		// If the caller isn't part of this package, we're done
+		if pkg != logrusPackage {
 			if fullFuncName == "main.main" {
 				return "main"
 			} else {

examples/basic/basic.go

@@ -1,7 +1,7 @@
 package main
 
 import (
-	"github.com/Sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 )
 
 var log = logrus.New()

examples/hook/hook.go

@@ -1,8 +1,14 @@
+// +build ignore
+// Do NOT include the above line in your code. This is a build constraint used
+// to prevent import loops in the code whilst go get'ting it.
+// Read more about build constraints in golang here:
+// https://golang.org/pkg/go/build/#hdr-Build_Constraints
+
 package main
 
 import (
-	"github.com/Sirupsen/logrus"
-	"gopkg.in/gemnasium/logrus-airbrake-hook.v2"
+	"github.com/sirupsen/logrus"
+	airbrake "gopkg.in/gemnasium/logrus-airbrake-hook.v2"
 )
 
 var log = logrus.New()

hooks/syslog/README.md

@@ -5,8 +5,8 @@
 ```go
 import (
   "log/syslog"
-  "github.com/Sirupsen/logrus"
-  logrus_syslog "github.com/Sirupsen/logrus/hooks/syslog"
+  "github.com/sirupsen/logrus"
+  logrus_syslog "github.com/sirupsen/logrus/hooks/syslog"
 )
 
 func main() {
@@ -24,8 +24,8 @@ If you want to connect to local syslog (Ex. "/dev/log" or "/var/run/syslog" or "
 ```go
 import (
   "log/syslog"
-  "github.com/Sirupsen/logrus"
-  logrus_syslog "github.com/Sirupsen/logrus/hooks/syslog"
+  "github.com/sirupsen/logrus"
+  logrus_syslog "github.com/sirupsen/logrus/hooks/syslog"
 )
 
 func main() {

hooks/syslog/syslog.go

@@ -4,9 +4,10 @@ package logrus_syslog
 
 import (
 	"fmt"
-	"github.com/Sirupsen/logrus"
 	"log/syslog"
 	"os"
+
+	"github.com/sirupsen/logrus"
 )
 
 // SyslogHook to send logs via syslog.

hooks/syslog/syslog_test.go

@@ -1,9 +1,10 @@
 package logrus_syslog
 
 import (
-	"github.com/Sirupsen/logrus"
 	"log/syslog"
 	"testing"
+
+	"github.com/sirupsen/logrus"
 )
 
 func TestLocalhostAddAndPrint(t *testing.T) {

hooks/test/test.go

@@ -3,7 +3,7 @@ package test
 import (
 	"io/ioutil"
 
-	"github.com/Sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 )
 
 // test.Hook is a hook designed for dealing with logs in test scenarios.

hooks/test/test_test.go

@@ -3,7 +3,7 @@ package test
 import (
 	"testing"
 
-	"github.com/Sirupsen/logrus"
+	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 )
 

json_formatter.go

@@ -46,7 +46,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
 		switch v := v.(type) {
 		case error:
 			// Otherwise errors are ignored by `encoding/json`
-			// https://github.com/Sirupsen/logrus/issues/137
+			// https://github.com/sirupsen/logrus/issues/137
 			data[k] = v.Error()
 		default:
 			data[k] = v

logrus_test.go

@@ -7,6 +7,7 @@ import (
 	"strings"
 	"sync"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
 )
@@ -312,6 +313,53 @@ func TestNestedLoggingReportsCorrectCaller(t *testing.T) {
 	logger.ReportCaller = false // return to default value
 }
 
+func logLoop(iterations int, reportCaller bool) {
+	var buffer bytes.Buffer
+
+	logger := New()
+	logger.Out = &buffer
+	logger.Formatter = new(JSONFormatter)
+	logger.ReportCaller = reportCaller
+
+	for i := 0; i < iterations; i++ {
+		logger.Infof("round %d of %d", i, iterations)
+	}
+}
+
+// Assertions for upper bounds to reporting overhead
+func TestCallerReportingOverhead(t *testing.T) {
+	iterations := 10000
+	before := time.Now()
+	logLoop(iterations, false)
+	during := time.Now()
+	logLoop(iterations, true)
+	after := time.Now()
+
+	elapsedNotReporting := during.Sub(before).Nanoseconds()
+	elapsedReporting := after.Sub(during).Nanoseconds()
+
+	maxDelta := 1 * time.Second
+	assert.WithinDuration(t, during, before, maxDelta,
+		"%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)",
+		iterations, maxDelta.Seconds(), elapsedNotReporting)
+	assert.WithinDuration(t, after, during, maxDelta,
+		"%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)",
+		iterations, maxDelta.Seconds(), elapsedReporting)
+}
+
+// benchmarks for both with and without caller-function reporting
+func BenchmarkWithoutCallerTracing(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		logLoop(1000, false)
+	}
+}
+
+func BenchmarkWithCallerTracing(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		logLoop(1000, true)
+	}
+}
+
 func TestConvertLevelToString(t *testing.T) {
 	assert.Equal(t, "debug", DebugLevel.String())
 	assert.Equal(t, "info", InfoLevel.String())