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
This commit is contained in:
Dave Clendenan 2016-11-25 19:02:56 -08:00
parent a437dfd246
commit 93af604ba7
10 changed files with 248 additions and 20 deletions

View File

@ -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

View File

@ -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"

View File

@ -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)

View File

@ -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()

View File

@ -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
}
}
}

View File

@ -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)

View File

@ -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
}

View File

@ -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,
}
}

View File

@ -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())

View File

@ -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]