From 93af604ba7774ca16474f3485ab6fcf084606fe0 Mon Sep 17 00:00:00 2001 From: Dave Clendenan Date: Fri, 25 Nov 2016 19:02:56 -0800 Subject: [PATCH] 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]