From 433dbf97e6044d453e9bcd83dba9f407175cc25d Mon Sep 17 00:00:00 2001 From: derekdowling Date: Tue, 4 Nov 2014 09:04:58 -0700 Subject: [PATCH 1/4] Adding logtext formatter --- logtext.go | 48 ++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 48 insertions(+) create mode 100644 logtext.go diff --git a/logtext.go b/logtext.go new file mode 100644 index 000000000..0cc9b2c22 --- /dev/null +++ b/logtext.go @@ -0,0 +1,48 @@ +package logtext + +// A Logrus hook that adds filename/line number/stack trace to our log outputs + +import ( + "github.com/Sirupsen/logrus" + "runtime" +) + +// Log depth is how many levels to ascend to find where the actual log call occurred +// while debugOnly sets whether or not stack traces should be printed outside of +// debug prints +type Logtext struct{ + Formatter logrus.Formatter + LogDepth int + DebugOnly bool +} + +func NewLogtext(formatter logrus.Formatter, debugOnly bool) *Logtext { + return &Logtext{ + LogDepth: 4, + Formatter: formatter, + DebugOnly: debugOnly, + } +} + +// Creates a hook to be added to an instance of logger. This is called with +func (hook *Logtext) Format(entry *logrus.Entry) ([]byte, error) { + + if _, file, line, ok := runtime.Caller(hook.LogDepth); ok { + entry.Data["line"] = line + entry.Data["file"] = file + } + + if !hook.DebugOnly || entry.Level == logrus.DebugLevel { + stack := getTrace() + entry.Data["stack"] = stack + } + + return hook.Formatter.Format(entry) +} + +// handles getting the stack trace and returns it as a string +func getTrace() string { + stack := make([]byte, 2048) + size := runtime.Stack(stack, false) + return string(stack[:size]) +} From 5b8726871893ffcc42b202606ee9194dbd00a4af Mon Sep 17 00:00:00 2001 From: derekdowling Date: Sun, 9 Nov 2014 09:23:09 -0700 Subject: [PATCH 2/4] Made file name/line number part of logrus core --- entry.go | 25 +++++++++++++++++++++++++ logrus_test.go | 2 ++ logtext.go | 48 ------------------------------------------------ 3 files changed, 27 insertions(+), 48 deletions(-) delete mode 100644 logtext.go diff --git a/entry.go b/entry.go index 9ae900bc5..2bd41571a 100644 --- a/entry.go +++ b/entry.go @@ -5,7 +5,11 @@ import ( "fmt" "io" "os" + "runtime" + "strconv" + "strings" "time" + "path/filepath" ) // Defines the key when adding errors using WithError. @@ -84,6 +88,11 @@ func (entry Entry) log(level Level, msg string) { entry.Time = time.Now() entry.Level = level entry.Message = msg + entry.Data["caller"] = context() + + // if level == WarnLevel || level == InfoLevel { + // entry.Data["trace"] = trace() + // } if err := entry.Logger.Hooks.Fire(level, &entry); err != nil { entry.Logger.mu.Lock() @@ -262,3 +271,19 @@ func (entry *Entry) sprintlnn(args ...interface{}) string { msg := fmt.Sprintln(args...) return msg[:len(msg)-1] } + +// Captures where the log call came from and formats it for output +func context() string { + if _, file, line, ok := runtime.Caller(4); ok { + return strings.Join([]string{filepath.Base(file), strconv.Itoa(line)}, ":") + } + // not sure what the convention should be here + return "unavailable" +} + +// handles getting the stack trace and returns it as a string +func trace() string { + stack := make([]byte, 2048) + size := runtime.Stack(stack, false) + return string(stack[:size]) +} diff --git a/logrus_test.go b/logrus_test.go index efaacea23..252423eeb 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -62,6 +62,7 @@ func TestPrint(t *testing.T) { }, func(fields Fields) { assert.Equal(t, fields["msg"], "test") assert.Equal(t, fields["level"], "info") + assert.Equal(t, fields["caller"], "logrus_test.go:56") }) } @@ -71,6 +72,7 @@ func TestInfo(t *testing.T) { }, func(fields Fields) { assert.Equal(t, fields["msg"], "test") assert.Equal(t, fields["level"], "info") + assert.Equal(t, fields["caller"], "logrus_test.go:66") }) } diff --git a/logtext.go b/logtext.go deleted file mode 100644 index 0cc9b2c22..000000000 --- a/logtext.go +++ /dev/null @@ -1,48 +0,0 @@ -package logtext - -// A Logrus hook that adds filename/line number/stack trace to our log outputs - -import ( - "github.com/Sirupsen/logrus" - "runtime" -) - -// Log depth is how many levels to ascend to find where the actual log call occurred -// while debugOnly sets whether or not stack traces should be printed outside of -// debug prints -type Logtext struct{ - Formatter logrus.Formatter - LogDepth int - DebugOnly bool -} - -func NewLogtext(formatter logrus.Formatter, debugOnly bool) *Logtext { - return &Logtext{ - LogDepth: 4, - Formatter: formatter, - DebugOnly: debugOnly, - } -} - -// Creates a hook to be added to an instance of logger. This is called with -func (hook *Logtext) Format(entry *logrus.Entry) ([]byte, error) { - - if _, file, line, ok := runtime.Caller(hook.LogDepth); ok { - entry.Data["line"] = line - entry.Data["file"] = file - } - - if !hook.DebugOnly || entry.Level == logrus.DebugLevel { - stack := getTrace() - entry.Data["stack"] = stack - } - - return hook.Formatter.Format(entry) -} - -// handles getting the stack trace and returns it as a string -func getTrace() string { - stack := make([]byte, 2048) - size := runtime.Stack(stack, false) - return string(stack[:size]) -} From 572caaba87ca9fd15e5e7726636a3b65f688443a Mon Sep 17 00:00:00 2001 From: Derek Dowling Date: Mon, 26 Oct 2015 22:17:23 -0700 Subject: [PATCH 3/4] Isolating down to just trace logic --- entry.go | 41 +++++++++++++++++------------------------ formatter.go | 5 +++++ json_formatter.go | 5 +++++ logger.go | 5 +++++ logrus_test.go | 17 ++++++++++++++--- 5 files changed, 46 insertions(+), 27 deletions(-) diff --git a/entry.go b/entry.go index 2bd41571a..2d38f0066 100644 --- a/entry.go +++ b/entry.go @@ -6,10 +6,7 @@ import ( "io" "os" "runtime" - "strconv" - "strings" "time" - "path/filepath" ) // Defines the key when adding errors using WithError. @@ -33,13 +30,17 @@ type Entry struct { // Message passed to Debug, Info, Warn, Error, Fatal or Panic Message string + + // Trace information + Trace string } func NewEntry(logger *Logger) *Entry { return &Entry{ Logger: logger, // Default is three fields, give a little extra room - Data: make(Fields, 5), + Data: make(Fields, 5), + Trace: "", } } @@ -82,17 +83,25 @@ func (entry *Entry) WithFields(fields Fields) *Entry { return &Entry{Logger: entry.Logger, Data: data} } +// WithTrace adds a stack trace back from where the log entry was created +func (entry *Entry) WithTrace() *Entry { + // don't actually do the trace here otherwise it'll be wrong + entry.Trace = "placeholder" + return entry +} + // 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) { entry.Time = time.Now() entry.Level = level entry.Message = msg - entry.Data["caller"] = context() - // if level == WarnLevel || level == InfoLevel { - // entry.Data["trace"] = trace() - // } + if entry.Trace == "placeholder" { + stack := make([]byte, 2048) + size := runtime.Stack(stack, false) + entry.Trace = string(stack[:size]) + } if err := entry.Logger.Hooks.Fire(level, &entry); err != nil { entry.Logger.mu.Lock() @@ -271,19 +280,3 @@ func (entry *Entry) sprintlnn(args ...interface{}) string { msg := fmt.Sprintln(args...) return msg[:len(msg)-1] } - -// Captures where the log call came from and formats it for output -func context() string { - if _, file, line, ok := runtime.Caller(4); ok { - return strings.Join([]string{filepath.Base(file), strconv.Itoa(line)}, ":") - } - // not sure what the convention should be here - return "unavailable" -} - -// handles getting the stack trace and returns it as a string -func trace() string { - stack := make([]byte, 2048) - size := runtime.Stack(stack, false) - return string(stack[:size]) -} diff --git a/formatter.go b/formatter.go index 104d689f1..388c1bbb4 100644 --- a/formatter.go +++ b/formatter.go @@ -45,4 +45,9 @@ func prefixFieldClashes(data Fields) { if ok { data["fields.level"] = data["level"] } + + _, ok = data["trace"] + if ok { + data["fields.trace"] = data["trace"] + } } diff --git a/json_formatter.go b/json_formatter.go index 2ad6dc5cf..f92ea2d6a 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -33,6 +33,11 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data["msg"] = entry.Message data["level"] = entry.Level.String() + // Only add trace if it was built + if entry.Trace != "" { + data["trace"] = entry.Trace + } + serialized, err := json.Marshal(data) if err != nil { return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err) diff --git a/logger.go b/logger.go index fd9804c64..eb459539d 100644 --- a/logger.go +++ b/logger.go @@ -64,6 +64,11 @@ func (logger *Logger) WithFields(fields Fields) *Entry { return NewEntry(logger).WithFields(fields) } +// WithTrace creates a new log entry with a captured trace from the current location +func (logger *Logger) WithTrace() *Entry { + return NewEntry(logger).WithTrace() +} + func (logger *Logger) Debugf(format string, args ...interface{}) { if logger.Level >= DebugLevel { NewEntry(logger).Debugf(format, args...) diff --git a/logrus_test.go b/logrus_test.go index 252423eeb..e9c355990 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -62,7 +62,7 @@ func TestPrint(t *testing.T) { }, func(fields Fields) { assert.Equal(t, fields["msg"], "test") assert.Equal(t, fields["level"], "info") - assert.Equal(t, fields["caller"], "logrus_test.go:56") + assert.Nil(t, fields["trace"]) }) } @@ -72,7 +72,7 @@ func TestInfo(t *testing.T) { }, func(fields Fields) { assert.Equal(t, fields["msg"], "test") assert.Equal(t, fields["level"], "info") - assert.Equal(t, fields["caller"], "logrus_test.go:66") + assert.Nil(t, fields["trace"]) }) } @@ -82,6 +82,17 @@ func TestWarn(t *testing.T) { }, func(fields Fields) { assert.Equal(t, fields["msg"], "test") assert.Equal(t, fields["level"], "warning") + assert.Nil(t, fields["trace"]) + }) +} + +func TestWithTrace(t *testing.T) { + LogAndAssertJSON(t, func(log *Logger) { + log.WithTrace().Warn("test") + }, func(fields Fields) { + assert.Equal(t, fields["msg"], "test") + assert.Equal(t, fields["level"], "warning") + assert.NotNil(t, fields["trace"]) }) } @@ -236,7 +247,7 @@ 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, len(fields), 4, "should only have msg/time/level/context/caller fields") assert.Equal(t, fields["msg"], "omg it is!") assert.Equal(t, fields["context"], "eating raw fish") assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") From 6765e7f4979d2a264603df4f62a84d0edb0b147e Mon Sep 17 00:00:00 2001 From: Derek Dowling Date: Mon, 26 Oct 2015 22:25:41 -0700 Subject: [PATCH 4/4] Undoing assertion message update --- logrus_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logrus_test.go b/logrus_test.go index e9c355990..c33ac7a00 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -247,7 +247,7 @@ 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/caller fields") + 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, fields["context"], "eating raw fish") assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry")