Use logrus ReportCaller to get file, line and function

gelf_writer.go

@@ -266,9 +266,6 @@ func (w *Writer) Warning(m string) (err error)
 // the server specified in New().
 func (w *Writer) Write(p []byte) (n int, err error) {
 
-	// 1 for the function that called us.
-	file, line := getCallerIgnoringLogMulti(1)
-
 	// remove trailing and leading whitespace
 	p = bytes.TrimSpace(p)
 
@@ -291,8 +288,6 @@ func (w *Writer) Write(p []byte) (n int, err error) {
 		TimeUnix: float64(time.Now().UnixNano()/1000000) / 1000.,
 		Level:    6, // info
 		Facility: w.Facility,
-		File:     file,
-		Line:     line,
 		Extra:    map[string]interface{}{},
 	}
 

graylog_hook.go

@@ -6,8 +6,6 @@ import (
 	"errors"
 	"fmt"
 	"os"
-	"runtime"
-	"strings"
 	"sync"
 	"time"
 
@@ -95,9 +93,13 @@ func (hook *GraylogHook) Fire(entry *logrus.Entry) error {
 	hook.mu.RLock() // Claim the mutex as a RLock - allowing multiple go routines to log simultaneously
 	defer hook.mu.RUnlock()
 
-	// get caller file and line here, it won't be available inside the goroutine
-	// 1 for the function that called us.
-	file, line := getCallerIgnoringLogMulti(1)
+	var file string
+	var line int
+
+	if entry.Caller != nil {
+		file = entry.Caller.File
+		line = entry.Caller.Line
+	}
 
 	newData := make(map[string]interface{})
 	for k, v := range entry.Data {
@@ -109,6 +111,7 @@ func (hook *GraylogHook) Fire(entry *logrus.Entry) error {
 		Data:    newData,
 		Time:    entry.Time,
 		Level:   entry.Level,
+		Caller:  entry.Caller,
 		Message: entry.Message,
 	}
 	gEntry := graylogEntry{newEntry, file, line}
@@ -182,6 +185,13 @@ func (hook *GraylogHook) sendEntry(entry graylogEntry) {
 		k = fmt.Sprintf("_%s", k) // "[...] every field you send and prefix with a _ (underscore) will be treated as an additional field."
 		extra[k] = v
 	}
+
+	if entry.Caller != nil {
+		extra["_file"] = entry.Caller.File
+		extra["_line"] = entry.Caller.Line
+		extra["_function"] = entry.Caller.Function
+	}
+
 	for k, v := range entry.Data {
 		if !hook.blacklist[k] {
 			extraK := fmt.Sprintf("_%s", k) // "[...] every field you send and prefix with a _ (underscore) will be treated as an additional field."
@@ -258,38 +268,3 @@ func (hook *GraylogHook) SetWriter(w *Writer) error {
 func (hook *GraylogHook) Writer() *Writer {
 	return hook.gelfLogger
 }
-
-// getCaller returns the filename and the line info of a function
-// further down in the call stack.  Passing 0 in as callDepth would
-// return info on the function calling getCallerIgnoringLog, 1 the
-// parent function, and so on.  Any suffixes passed to getCaller are
-// path fragments like "/pkg/log/log.go", and functions in the call
-// stack from that file are ignored.
-func getCaller(callDepth int, suffixesToIgnore ...string) (file string, line int) {
-	// bump by 1 to ignore the getCaller (this) stackframe
-	callDepth++
-outer:
-	for {
-		var ok bool
-		_, file, line, ok = runtime.Caller(callDepth)
-		if !ok {
-			file = "???"
-			line = 0
-			break
-		}
-
-		for _, s := range suffixesToIgnore {
-			if strings.HasSuffix(file, s) {
-				callDepth++
-				continue outer
-			}
-		}
-		break
-	}
-	return
-}
-
-func getCallerIgnoringLogMulti(callDepth int) (string, int) {
-	// the +1 is to ignore this (getCallerIgnoringLogMulti) frame
-	return getCaller(callDepth+1, "logrus/hooks.go", "logrus/entry.go", "logrus/logger.go", "logrus/exported.go", "asm_amd64.s")
-}

graylog_hook_test.go

@@ -29,6 +29,7 @@ func TestWritingToUDP(t *testing.T) {
 	msgData := "test message\nsecond line"
 
 	log := logrus.New()
+	log.SetReportCaller(true)
 	log.Out = ioutil.Discard
 	log.Hooks.Add(hook)
 	log.WithFields(logrus.Fields{"withField": "1", "filterMe": "1"}).Info(msgData)
@@ -55,8 +56,8 @@ func TestWritingToUDP(t *testing.T) {
 		t.Errorf("Host should match (exp: testing.local, got: %s)", msg.Host)
 	}
 
-	if len(msg.Extra) != 2 {
-		t.Errorf("wrong number of extra fields (exp: %d, got %d) in %v", 2, len(msg.Extra), msg.Extra)
+	if len(msg.Extra) != 5 {
+		t.Errorf("wrong number of extra fields (exp: %d, got %d) in %v", 5, len(msg.Extra), msg.Extra)
 	}
 
 	fileExpected := "graylog_hook_test.go"
@@ -65,12 +66,12 @@ func TestWritingToUDP(t *testing.T) {
 			msg.File)
 	}
 
-	lineExpected := 34 // Update this if code is updated above
+	lineExpected := 35 // Update this if code is updated above
 	if msg.Line != lineExpected {
 		t.Errorf("msg.Line: expected %d, got %d", lineExpected, msg.Line)
 	}
 
-	if len(msg.Extra) != 2 {
+	if len(msg.Extra) != 5 {
 		t.Errorf("wrong number of extra fields (exp: %d, got %d) in %v", 2, len(msg.Extra), msg.Extra)
 	}
 
@@ -251,6 +252,7 @@ func TestStackTracer(t *testing.T) {
 	hook := NewGraylogHook(r.Addr(), map[string]interface{}{})
 
 	log := logrus.New()
+	log.SetReportCaller(true)
 	log.Out = ioutil.Discard
 	log.Hooks.Add(hook)
 
@@ -269,7 +271,7 @@ func TestStackTracer(t *testing.T) {
 			msg.File)
 	}
 
-	lineExpected := 257 // Update this if code is updated above
+	lineExpected := 259 // Update this if code is updated above
 	if msg.Line != lineExpected {
 		t.Errorf("msg.Line: expected %d, got %d", lineExpected, msg.Line)
 	}
@@ -331,3 +333,127 @@ func TestLogrusLevelToSylog(t *testing.T) {
 		t.Error("logrusLevelToSylog(PanicLevel) != LOG_ALERT")
 	}
 }
+
+func TestReportCallerEnabled(t *testing.T) {
+	r, err := NewReader("127.0.0.1:0")
+	if err != nil {
+		t.Fatalf("NewReader: %s", err)
+	}
+	hook := NewGraylogHook(r.Addr(), map[string]interface{}{})
+	hook.Host = "testing.local"
+	msgData := "test message\nsecond line"
+
+	log := logrus.New()
+	log.SetReportCaller(true)
+	log.Out = ioutil.Discard
+	log.Hooks.Add(hook)
+	log.Info(msgData)
+
+	msg, err := r.ReadMessage()
+
+	if err != nil {
+		t.Errorf("ReadMessage: %s", err)
+	}
+
+	fileField, ok := msg.Extra["_file"]
+	if !ok {
+		t.Error("_file field not present in extra fields")
+	}
+
+	fileGot, ok := fileField.(string)
+	if !ok {
+		t.Error("_file field is not a string")
+	}
+
+	fileExpected := "graylog_hook_test.go"
+	if !strings.HasSuffix(fileGot, fileExpected) {
+		t.Errorf("msg.Extra[\"_file\"]: expected %s, got %s", fileExpected, fileGot)
+	}
+
+	lineField, ok := msg.Extra["_line"]
+	if !ok {
+		t.Error("_line field not present in extra fields")
+	}
+
+	lineGot, ok := lineField.(float64)
+	if !ok {
+		t.Error("_line dowes not have the correct type")
+	}
+
+	lineExpected := 350 // Update this if code is updated above
+	if msg.Line != lineExpected {
+		t.Errorf("msg.Extra[\"_line\"]: expected %d, got %d", lineExpected, int(lineGot))
+	}
+
+	functionField, ok := msg.Extra["_function"]
+	if !ok {
+		t.Error("_function field not present in extra fields")
+	}
+
+	functionGot, ok := functionField.(string)
+	if !ok {
+		t.Error("_function field is not a string")
+	}
+
+	functionExpected := "TestReportCallerEnabled"
+	if !strings.HasSuffix(functionGot, functionExpected) {
+		t.Errorf("msg.Extra[\"_function\"]: expected %s, got %s", functionExpected, functionGot)
+	}
+
+	gelfFileExpected := "graylog_hook_test.go"
+	if !strings.HasSuffix(msg.File, gelfFileExpected) {
+		t.Errorf("msg.File: expected %s, got %s", gelfFileExpected,
+			msg.File)
+	}
+
+	gelfLineExpected := 259 // Update this if code is updated above
+	if msg.Line != lineExpected {
+		t.Errorf("msg.Line: expected %d, got %d", gelfLineExpected, msg.Line)
+	}
+}
+
+func TestReportCallerDisabled(t *testing.T) {
+	r, err := NewReader("127.0.0.1:0")
+	if err != nil {
+		t.Fatalf("NewReader: %s", err)
+	}
+	hook := NewGraylogHook(r.Addr(), map[string]interface{}{})
+	hook.Host = "testing.local"
+	msgData := "test message\nsecond line"
+
+	log := logrus.New()
+	log.SetReportCaller(false)
+	log.Out = ioutil.Discard
+	log.Hooks.Add(hook)
+	log.Info(msgData)
+
+	msg, err := r.ReadMessage()
+
+	if err != nil {
+		t.Errorf("ReadMessage: %s", err)
+	}
+
+	if _, ok := msg.Extra["_file"]; ok {
+		t.Error("_file field should not present in extra fields")
+	}
+
+	if _, ok := msg.Extra["_line"]; ok {
+		t.Error("_line field should not present in extra fields")
+	}
+
+	if _, ok := msg.Extra["_function"]; ok {
+		t.Error("_function field should not present in extra fields")
+	}
+
+	// if reportCaller is disabled (this is the default setting) the File and Line field should have the default values
+	// corresponding to the types. "" and 0 respectively.
+	gelfFileExpected := ""
+	if msg.File != gelfFileExpected {
+		t.Errorf("msg.File: expected %s, got %s", gelfFileExpected, msg.File)
+	}
+
+	gelfLineExpected := 0
+	if msg.Line != gelfLineExpected {
+		t.Errorf("msg.Line: expected %d, got %d", gelfLineExpected, msg.Line)
+	}
+}