Merge pull request #850 from sirupsen/caller_feature

Add optional log field with calling method

README.md

@@ -56,8 +56,39 @@ time="2015-03-26T01:27:38-04:00" level=warning msg="The group's number increased
 time="2015-03-26T01:27:38-04:00" level=debug msg="Temperature changes" temperature=-4
 time="2015-03-26T01:27:38-04:00" level=panic msg="It's over 9000!" animal=orca size=9009
 time="2015-03-26T01:27:38-04:00" level=fatal msg="The ice breaks!" err=&{0x2082280c0 map[animal:orca size:9009] 2015-03-26 01:27:38.441574009 -0400 EDT panic It's over 9000!} number=100 omg=true
-exit status 1
 ```
+To ensure this behaviour even if a TTY is attached, set your formatter as follows:
+
+```go
+	log.SetFormatter(&log.TextFormatter{
+		DisableColors: true,
+		FullTimestamp: true,
+	})
+```
+
+#### Logging Method Name
+
+If you wish to add the calling method as a field, instruct the logger via:
+```go
+log.SetReportCaller(true)
+```
+This adds the caller as 'method' like so:
+
+```json
+{"animal":"penguin","level":"fatal","method":"github.com/sirupsen/arcticcreatures.migrate","msg":"a penguin swims by",
+"time":"2014-03-10 19:57:38.562543129 -0400 EDT"}
+```
+
+```text
+time="2015-03-26T01:27:38-04:00" level=fatal method=github.com/sirupsen/arcticcreatures.migrate msg="a penguin swims by" animal=penguin
+```
+Note that this does add measurable overhead - the cost will depend on the version of Go, but is
+between 20 and 40% in recent tests with 1.6 and 1.7.  You can validate this in your
+environment via benchmarks: 
+```
+go test -bench=.*CallerTracing
+```
+
 
 #### Case-sensitivity
 

alt_exit_test.go

@@ -6,6 +6,8 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"runtime"
+	"strings"
 	"testing"
 	"time"
 )
@@ -19,6 +21,9 @@ func TestRegister(t *testing.T) {
 }
 
 func TestHandler(t *testing.T) {
+	testprog := testprogleader
+	testprog = append(testprog, getPackage()...)
+	testprog = append(testprog, testprogtrailer...)
 	tempDir, err := ioutil.TempDir("", "test_handler")
 	if err != nil {
 		log.Fatalf("can't create temp dir. %q", err)
@@ -47,13 +52,24 @@ func TestHandler(t *testing.T) {
 	}
 }
 
-var testprog = []byte(`
+// getPackage returns the name of the current package, which makes running this
+// test in a fork simpler
+func getPackage() []byte {
+	pc, _, _, _ := runtime.Caller(0)
+	fullFuncName := runtime.FuncForPC(pc).Name()
+	idx := strings.LastIndex(fullFuncName, ".")
+	return []byte(fullFuncName[:idx]) // trim off function details
+}
+
+var testprogleader = []byte(`
 // Test program for atexit, gets output file and data as arguments and writes
 // data to output file in atexit handler.
 package main
 
 import (
-	"github.com/sirupsen/logrus"
+	"`)
+var testprogtrailer = []byte(
+	`"
 	"flag"
 	"fmt"
 	"io/ioutil"

entry.go

@@ -5,11 +5,29 @@ import (
 	"fmt"
 	"os"
 	"reflect"
+	"runtime"
+	"strings"
 	"sync"
 	"time"
 )
 
-var bufferPool *sync.Pool
+var (
+	bufferPool *sync.Pool
+
+	// qualified package name, cached at first use
+	logrusPackage string
+
+	// Positions in the call stack when tracing to report the calling method
+	minimumCallerDepth int
+
+	// Used for caller information initialisation
+	callerInitOnce sync.Once
+)
+
+const (
+	maximumCallerDepth int = 25
+	knownLogrusFrames  int = 4
+)
 
 func init() {
 	bufferPool = &sync.Pool{
@@ -17,6 +35,9 @@ func init() {
 			return new(bytes.Buffer)
 		},
 	}
+
+	// start at the bottom of the stack before the package-name cache is primed
+	minimumCallerDepth = 1
 }
 
 // Defines the key when adding errors using WithError.
@@ -39,6 +60,9 @@ type Entry struct {
 	// This field will be set on entry firing and the value will be equal to the one in Logger struct field.
 	Level Level
 
+	// Calling method, with package name
+	Caller *runtime.Frame
+
 	// Message passed to Trace, Debug, Info, Warn, Error, Fatal or Panic
 	Message string
 
@@ -52,8 +76,8 @@ type Entry struct {
 func NewEntry(logger *Logger) *Entry {
 	return &Entry{
 		Logger: logger,
-		// Default is five fields, give a little extra room
+		// Default is three fields, plus one optional.  Give a little extra room.
-		Data: make(Fields, 5),
+		Data: make(Fields, 6),
 	}
 }
 
@@ -103,6 +127,57 @@ func (entry *Entry) WithTime(t time.Time) *Entry {
 	return &Entry{Logger: entry.Logger, Data: entry.Data, Time: t}
 }
 
+// getPackageName reduces a fully qualified function name to the package name
+// There really ought to be to be a better way...
+func getPackageName(f string) string {
+	for {
+		lastPeriod := strings.LastIndex(f, ".")
+		lastSlash := strings.LastIndex(f, "/")
+		if lastPeriod > lastSlash {
+			f = f[:lastPeriod]
+		} else {
+			break
+		}
+	}
+
+	return f
+}
+
+// getCaller retrieves the name of the first non-logrus calling function
+func getCaller() *runtime.Frame {
+	// Restrict the lookback frames to avoid runaway lookups
+	pcs := make([]uintptr, maximumCallerDepth)
+	depth := runtime.Callers(minimumCallerDepth, pcs)
+	frames := runtime.CallersFrames(pcs[:depth])
+
+	// cache this package's fully-qualified name
+	callerInitOnce.Do(func() {
+		logrusPackage = getPackageName(runtime.FuncForPC(pcs[0]).Name())
+
+		// now that we have the cache, we can skip a minimum count of known-logrus functions
+		// XXX this is dubious, the number of frames may vary store an entry in a logger interface
+		minimumCallerDepth = knownLogrusFrames
+	})
+
+	for f, again := frames.Next(); again; f, again = frames.Next() {
+		pkg := getPackageName(f.Function)
+
+		// If the caller isn't part of this package, we're done
+		if pkg != logrusPackage {
+			return &f
+		}
+	}
+
+	// if we got here, we failed to find the caller's context
+	return nil
+}
+
+func (entry Entry) HasCaller() (has bool) {
+	return entry.Logger != nil &&
+		entry.Logger.ReportCaller &&
+		entry.Caller != nil
+}
+
 // This function is not declared with a pointer value because otherwise
 // race conditions will occur when using multiple goroutines
 func (entry Entry) log(level Level, msg string) {
@@ -119,6 +194,9 @@ func (entry Entry) log(level Level, msg string) {
 
 	entry.Level = level
 	entry.Message = msg
+	if entry.Logger.ReportCaller {
+		entry.Caller = getCaller()
+	}
 
 	entry.fireHooks()
 

exported.go

@@ -24,6 +24,12 @@ func SetFormatter(formatter Formatter) {
 	std.SetFormatter(formatter)
 }
 
+// SetReportCaller sets whether the standard logger will include the calling
+// method as a field.
+func SetReportCaller(include bool) {
+	std.SetReportCaller(include)
+}
+
 // SetLevel sets the standard logger level.
 func SetLevel(level Level) {
 	std.SetLevel(level)

formatter.go

@@ -9,6 +9,8 @@ const (
 	FieldKeyLevel          = "level"
 	FieldKeyTime           = "time"
 	FieldKeyLogrusError    = "logrus_error"
+	FieldKeyFunc           = "func"
+	FieldKeyFile           = "file"
 )
 
 // The Formatter interface is used to implement a custom Formatter. It takes an
@@ -25,7 +27,7 @@ type Formatter interface {
 	Format(*Entry) ([]byte, error)
 }
 
-// This is to not silently overwrite `time`, `msg` and `level` fields when
+// This is to not silently overwrite `time`, `msg`, `func` and `level` fields when
 // dumping it. If this code wasn't there doing:
 //
 //  logrus.WithField("level", 1).Info("hello")
@@ -37,7 +39,7 @@ type Formatter interface {
 //
 // It's not exported because it's still using Data in an opinionated way. It's to
 // avoid code duplication between the two default formatters.
-func prefixFieldClashes(data Fields, fieldMap FieldMap) {
+func prefixFieldClashes(data Fields, fieldMap FieldMap, reportCaller bool) {
 	timeKey := fieldMap.resolve(FieldKeyTime)
 	if t, ok := data[timeKey]; ok {
 		data["fields."+timeKey] = t
@@ -61,4 +63,16 @@ func prefixFieldClashes(data Fields, fieldMap FieldMap) {
 		data["fields."+logrusErrKey] = l
 		delete(data, logrusErrKey)
 	}
+
+	// If reportCaller is not set, 'func' will not conflict.
+	if reportCaller {
+		funcKey := fieldMap.resolve(FieldKeyFunc)
+		if l, ok := data[funcKey]; ok {
+			data["fields."+funcKey] = l
+		}
+		fileKey := fieldMap.resolve(FieldKeyFile)
+		if l, ok := data[fileKey]; ok {
+			data["fields."+fileKey] = l
+		}
+	}
 }

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 {

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)
+}

json_formatter.go

@@ -37,6 +37,7 @@ type JSONFormatter struct {
 	// 		 FieldKeyTime:  "@timestamp",
 	// 		 FieldKeyLevel: "@level",
 	// 		 FieldKeyMsg:   "@message",
+	// 		 FieldKeyFunc:  "@caller",
 	//    },
 	// }
 	FieldMap FieldMap
@@ -47,7 +48,7 @@ type JSONFormatter struct {
 
 // Format renders a single log entry
 func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
-	data := make(Fields, len(entry.Data)+3)
+	data := make(Fields, len(entry.Data)+4)
 	for k, v := range entry.Data {
 		switch v := v.(type) {
 		case error:
@@ -65,7 +66,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
 		data = newData
 	}
 
-	prefixFieldClashes(data, f.FieldMap)
+	prefixFieldClashes(data, f.FieldMap, entry.HasCaller())
 
 	timestampFormat := f.TimestampFormat
 	if timestampFormat == "" {
@@ -80,6 +81,10 @@ 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.Function
+		data[f.FieldMap.resolve(FieldKeyFile)] = fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line)
+	}
 
 	var b *bytes.Buffer
 	if entry.Buffer != nil {

json_formatter_test.go

@@ -4,6 +4,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"runtime"
 	"strings"
 	"testing"
 )
@@ -267,6 +268,55 @@ func TestJSONTimeKey(t *testing.T) {
 	}
 }
 
+func TestFieldDoesNotClashWithCaller(t *testing.T) {
+	SetReportCaller(false)
+	formatter := &JSONFormatter{}
+
+	b, err := formatter.Format(WithField("func", "howdy pardner"))
+	if err != nil {
+		t.Fatal("Unable to format entry: ", err)
+	}
+
+	entry := make(map[string]interface{})
+	err = json.Unmarshal(b, &entry)
+	if err != nil {
+		t.Fatal("Unable to unmarshal formatted entry: ", err)
+	}
+
+	if entry["func"] != "howdy pardner" {
+		t.Fatal("func field replaced when ReportCaller=false")
+	}
+}
+
+func TestFieldClashWithCaller(t *testing.T) {
+	SetReportCaller(true)
+	formatter := &JSONFormatter{}
+	e := WithField("func", "howdy pardner")
+	e.Caller = &runtime.Frame{Function: "somefunc"}
+	b, err := formatter.Format(e)
+	if err != nil {
+		t.Fatal("Unable to format entry: ", err)
+	}
+
+	entry := make(map[string]interface{})
+	err = json.Unmarshal(b, &entry)
+	if err != nil {
+		t.Fatal("Unable to unmarshal formatted entry: ", err)
+	}
+
+	if entry["fields.func"] != "howdy pardner" {
+		t.Fatalf("fields.func not set to original func field when ReportCaller=true (got '%s')",
+			entry["fields.func"])
+	}
+
+	if entry["func"] != "somefunc" {
+		t.Fatalf("func not set as expected when ReportCaller=true (got '%s')",
+			entry["func"])
+	}
+
+	SetReportCaller(false) // return to default value
+}
+
 func TestJSONDisableTimestamp(t *testing.T) {
 	formatter := &JSONFormatter{
 		DisableTimestamp: true,

logger.go

@@ -24,6 +24,10 @@ type Logger struct {
 	// own that implements the `Formatter` interface, see the `README` or included
 	// formatters for examples.
 	Formatter Formatter
+
+	// Flag for whether to log caller info (off by default)
+	ReportCaller bool
+
 	// The logging level the logger should log at. This is typically (and defaults
 	// to) `logrus.Info`, which allows Info(), Warn(), Error() and Fatal() to be
 	// logged.
@@ -78,6 +82,7 @@ func New() *Logger {
 		Hooks:        make(LevelHooks),
 		Level:        InfoLevel,
 		ExitFunc:     os.Exit,
+		ReportCaller: false,
 	}
 }
 
@@ -394,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()

logrus_test.go

@@ -1,69 +1,93 @@
-package logrus
+package logrus_test
 
 import (
 	"bytes"
 	"encoding/json"
 	"io/ioutil"
-	"strconv"
+	"os"
-	"strings"
+	"path/filepath"
 	"sync"
 	"testing"
 	"time"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+
+	. "github.com/sirupsen/logrus"
+	. "github.com/sirupsen/logrus/internal/testutils"
 )
 
-func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) {
+// TestReportCaller verifies that when ReportCaller is set, the 'func' field
+// is added, and when it is unset it is not set or modified
+// Verify that functions within the Logrus package aren't considered when
+// discovering the caller.
+func TestReportCallerWhenConfigured(t *testing.T) {
+	LogAndAssertJSON(t, func(log *Logger) {
+		log.ReportCaller = false
+		log.Print("testNoCaller")
+	}, func(fields Fields) {
+		assert.Equal(t, "testNoCaller", fields["msg"])
+		assert.Equal(t, "info", fields["level"])
+		assert.Equal(t, nil, fields["func"])
+	})
+
+	LogAndAssertJSON(t, func(log *Logger) {
+		log.ReportCaller = true
+		log.Print("testWithCaller")
+	}, func(fields Fields) {
+		assert.Equal(t, "testWithCaller", fields["msg"])
+		assert.Equal(t, "info", fields["level"])
+		assert.Equal(t,
+			"github.com/sirupsen/logrus_test.TestReportCallerWhenConfigured.func3", fields["func"])
+	})
+}
+
+func logSomething(t *testing.T, message string) Fields {
 	var buffer bytes.Buffer
 	var fields Fields
 
 	logger := New()
 	logger.Out = &buffer
 	logger.Formatter = new(JSONFormatter)
+	logger.ReportCaller = true
 
-	log(logger)
+	entry := logger.WithFields(Fields{
+		"foo": "bar",
+	})
+
+	entry.Info(message)
 
 	err := json.Unmarshal(buffer.Bytes(), &fields)
 	assert.Nil(t, err)
 
-	assertions(fields)
+	return fields
 }
 
-func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields map[string]string)) {
+// TestReportCallerHelperDirect - verify reference when logging from a regular function
-	var buffer bytes.Buffer
+func TestReportCallerHelperDirect(t *testing.T) {
+	fields := logSomething(t, "direct")
 
-	logger := New()
+	assert.Equal(t, "direct", fields["msg"])
-	logger.Out = &buffer
+	assert.Equal(t, "info", fields["level"])
-	logger.Formatter = &TextFormatter{
+	assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"])
-		DisableColors: true,
 }
 
-	log(logger)
+// TestReportCallerHelperDirect - verify reference when logging from a function called via pointer
+func TestReportCallerHelperViaPointer(t *testing.T) {
+	fptr := logSomething
+	fields := fptr(t, "via pointer")
 
-	fields := make(map[string]string)
+	assert.Equal(t, "via pointer", fields["msg"])
-	for _, kv := range strings.Split(buffer.String(), " ") {
+	assert.Equal(t, "info", fields["level"])
-		if !strings.Contains(kv, "=") {
+	assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"])
-			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)
 }
 
 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, "test", fields["msg"])
-		assert.Equal(t, fields["level"], "info")
+		assert.Equal(t, "info", fields["level"])
 	})
 }
 
@@ -71,8 +95,8 @@ func TestInfo(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Info("test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "test")
+		assert.Equal(t, "test", fields["msg"])
-		assert.Equal(t, fields["level"], "info")
+		assert.Equal(t, "info", fields["level"])
 	})
 }
 
@@ -80,8 +104,8 @@ func TestWarn(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Warn("test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "test")
+		assert.Equal(t, "test", fields["msg"])
-		assert.Equal(t, fields["level"], "warning")
+		assert.Equal(t, "warning", fields["level"])
 	})
 }
 
@@ -89,7 +113,7 @@ func TestInfolnShouldAddSpacesBetweenStrings(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Infoln("test", "test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "test test")
+		assert.Equal(t, "test test", fields["msg"])
 	})
 }
 
@@ -97,7 +121,7 @@ func TestInfolnShouldAddSpacesBetweenStringAndNonstring(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Infoln("test", 10)
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "test 10")
+		assert.Equal(t, "test 10", fields["msg"])
 	})
 }
 
@@ -105,7 +129,7 @@ func TestInfolnShouldAddSpacesBetweenTwoNonStrings(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Infoln(10, 10)
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "10 10")
+		assert.Equal(t, "10 10", fields["msg"])
 	})
 }
 
@@ -113,7 +137,7 @@ func TestInfoShouldAddSpacesBetweenTwoNonStrings(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Infoln(10, 10)
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "10 10")
+		assert.Equal(t, "10 10", fields["msg"])
 	})
 }
 
@@ -121,7 +145,7 @@ func TestInfoShouldNotAddSpacesBetweenStringAndNonstring(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Info("test", 10)
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "test10")
+		assert.Equal(t, "test10", fields["msg"])
 	})
 }
 
@@ -129,7 +153,7 @@ func TestInfoShouldNotAddSpacesBetweenStrings(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.Info("test", "test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "testtest")
+		assert.Equal(t, "testtest", fields["msg"])
 	})
 }
 
@@ -167,7 +191,7 @@ func TestUserSuppliedFieldDoesNotOverwriteDefaults(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.WithField("msg", "hello").Info("test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "test")
+		assert.Equal(t, "test", fields["msg"])
 	})
 }
 
@@ -175,8 +199,8 @@ func TestUserSuppliedMsgFieldHasPrefix(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.WithField("msg", "hello").Info("test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["msg"], "test")
+		assert.Equal(t, "test", fields["msg"])
-		assert.Equal(t, fields["fields.msg"], "hello")
+		assert.Equal(t, "hello", fields["fields.msg"])
 	})
 }
 
@@ -184,7 +208,7 @@ func TestUserSuppliedTimeFieldHasPrefix(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.WithField("time", "hello").Info("test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["fields.time"], "hello")
+		assert.Equal(t, "hello", fields["fields.time"])
 	})
 }
 
@@ -192,8 +216,8 @@ func TestUserSuppliedLevelFieldHasPrefix(t *testing.T) {
 	LogAndAssertJSON(t, func(log *Logger) {
 		log.WithField("level", 1).Info("test")
 	}, func(fields Fields) {
-		assert.Equal(t, fields["level"], "info")
+		assert.Equal(t, "info", fields["level"])
-		assert.Equal(t, fields["fields.level"], 1.0) // JSON has floats only
+		assert.Equal(t, 1.0, fields["fields.level"]) // JSON has floats only
 	})
 }
 
@@ -217,7 +241,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))
 	})
 }
 
@@ -227,7 +251,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")
 	})
 }
@@ -238,7 +262,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")
 	})
 }
@@ -296,12 +320,115 @@ 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, "omg it is!", fields["msg"])
-	assert.Equal(t, fields["context"], "eating raw fish")
+	assert.Equal(t, "eating raw fish", fields["context"])
 	assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry")
 
 }
 
+func TestNestedLoggingReportsCorrectCaller(t *testing.T) {
+	var buffer bytes.Buffer
+	var fields Fields
+
+	logger := New()
+	logger.Out = &buffer
+	logger.Formatter = new(JSONFormatter)
+	logger.ReportCaller = true
+
+	llog := logger.WithField("context", "eating raw fish")
+
+	llog.Info("looks delicious")
+
+	err := json.Unmarshal(buffer.Bytes(), &fields)
+	require.NoError(t, err, "should have decoded first message")
+	assert.Equal(t, 6, len(fields), "should have msg/time/level/func/context fields")
+	assert.Equal(t, "looks delicious", fields["msg"])
+	assert.Equal(t, "eating raw fish", fields["context"])
+	assert.Equal(t,
+		"github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"])
+	cwd, err := os.Getwd()
+	require.NoError(t, err)
+	assert.Equal(t, filepath.ToSlash(cwd+"/logrus_test.go:340"), filepath.ToSlash(fields["file"].(string)))
+
+	buffer.Reset()
+
+	logger.WithFields(Fields{
+		"Clyde": "Stubblefield",
+	}).WithFields(Fields{
+		"Jab'o": "Starks",
+	}).WithFields(Fields{
+		"uri": "https://www.youtube.com/watch?v=V5DTznu-9v0",
+	}).WithFields(Fields{
+		"func": "y drummer",
+	}).WithFields(Fields{
+		"James": "Brown",
+	}).Print("The hardest workin' man in show business")
+
+	err = json.Unmarshal(buffer.Bytes(), &fields)
+	assert.NoError(t, err, "should have decoded second message")
+	assert.Equal(t, 11, len(fields), "should have all builtin fields plus foo,bar,baz,...")
+	assert.Equal(t, "Stubblefield", fields["Clyde"])
+	assert.Equal(t, "Starks", fields["Jab'o"])
+	assert.Equal(t, "https://www.youtube.com/watch?v=V5DTznu-9v0", fields["uri"])
+	assert.Equal(t, "y drummer", fields["fields.func"])
+	assert.Equal(t, "Brown", fields["James"])
+	assert.Equal(t, "The hardest workin' man in show business", fields["msg"])
+	assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry")
+	assert.Equal(t,
+		"github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"])
+	require.NoError(t, err)
+	assert.Equal(t, filepath.ToSlash(cwd+"/logrus_test.go:365"), filepath.ToSlash(fields["file"].(string)))
+
+	logger.ReportCaller = false // return to default value
+}
+
+func logLoop(iterations int, reportCaller bool) {
+	var buffer bytes.Buffer
+
+	logger := New()
+	logger.Out = &buffer
+	logger.Formatter = new(JSONFormatter)
+	logger.ReportCaller = reportCaller
+
+	for i := 0; i < iterations; i++ {
+		logger.Infof("round %d of %d", i, iterations)
+	}
+}
+
+// Assertions for upper bounds to reporting overhead
+func TestCallerReportingOverhead(t *testing.T) {
+	iterations := 5000
+	before := time.Now()
+	logLoop(iterations, false)
+	during := time.Now()
+	logLoop(iterations, true)
+	after := time.Now()
+
+	elapsedNotReporting := during.Sub(before).Nanoseconds()
+	elapsedReporting := after.Sub(during).Nanoseconds()
+
+	maxDelta := 1 * time.Second
+	assert.WithinDuration(t, during, before, maxDelta,
+		"%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)",
+		iterations, maxDelta.Seconds(), elapsedNotReporting)
+	assert.WithinDuration(t, after, during, maxDelta,
+		"%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)",
+		iterations, maxDelta.Seconds(), elapsedReporting)
+}
+
+// benchmarks for both with and without caller-function reporting
+func BenchmarkWithoutCallerTracing(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		logLoop(1000, false)
+	}
+}
+
+func BenchmarkWithCallerTracing(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		logLoop(1000, true)
+	}
+}
+
 func TestConvertLevelToString(t *testing.T) {
 	assert.Equal(t, "trace", TraceLevel.String())
 	assert.Equal(t, "debug", DebugLevel.String())

text_formatter.go

@@ -107,7 +107,7 @@ func (f *TextFormatter) isColored() bool {
 
 // Format renders a single log entry
 func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
-	prefixFieldClashes(entry.Data, f.FieldMap)
+	prefixFieldClashes(entry.Data, f.FieldMap, entry.HasCaller())
 
 	keys := make([]string, 0, len(entry.Data))
 	for k := range entry.Data {
@@ -125,6 +125,10 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
 	if entry.err != "" {
 		fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLogrusError))
 	}
+	if entry.HasCaller() {
+		fixedKeys = append(fixedKeys,
+			f.FieldMap.resolve(FieldKeyFunc), f.FieldMap.resolve(FieldKeyFile))
+	}
 
 	if !f.DisableSorting {
 		if f.SortingFunc == nil {
@@ -169,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]
 			}
@@ -202,12 +210,19 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin
 	// the behavior of logrus text_formatter the same as the stdlib log package
 	entry.Message = strings.TrimSuffix(entry.Message, "\n")
 
+	caller := ""
+
+	if entry.HasCaller() {
+		caller = fmt.Sprintf("%s:%d %s()",
+			entry.Caller.File, entry.Caller.Line, entry.Caller.Function)
+	}
+
 	if f.DisableTimestamp {
-		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m %-44s ", levelColor, levelText, entry.Message)
+		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m%s %-44s ", levelColor, levelText, caller, entry.Message)
 	} else if !f.FullTimestamp {
-		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), entry.Message)
+		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d]%s %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), caller, entry.Message)
 	} else {
-		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %-44s ", levelColor, levelText, entry.Time.Format(timestampFormat), entry.Message)
+		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]%s %-44s ", levelColor, levelText, entry.Time.Format(timestampFormat), caller, entry.Message)
 	}
 	for _, k := range keys {
 		v := entry.Data[k]