Merge pull request #9 from mailgun/maxim/develop

Fix filename/funcname for levelfilter use

common/common.go

@@ -70,16 +70,20 @@ func GetLogrusCaller() *stack.FrameInfo {
 	var frames [32]uintptr
 
 	// iterate until we find non logrus function
-	length := runtime.Callers(3, frames[:])
+	length := runtime.Callers(5, frames[:])
 	for idx := 0; idx < (length - 1); idx++ {
 		pc := uintptr(frames[idx]) - 1
-		f := runtime.FuncForPC(pc)
-		funcName := f.Name()
-		if strings.Contains(strings.ToLower(funcName), "github.com/sirupsen") {
+		fn := runtime.FuncForPC(pc)
+		funcName := fn.Name()
+		if strings.Contains(strings.ToLower(funcName), "sirupsen/logrus") {
 			continue
 		}
-		filePath, lineNo := f.FileLine(pc)
-		return &stack.FrameInfo{File: filePath, Func: funcName, LineNo: lineNo}
+		filePath, lineNo := fn.FileLine(pc)
+		return &stack.FrameInfo{
+			Func:   stack.FuncName(fn),
+			File:   filePath,
+			LineNo: lineNo,
+		}
 	}
 	return &stack.FrameInfo{}
 }

common/log_record.go

@@ -41,7 +41,8 @@ func (r *LogRecord) FromFields(fields logrus.Fields) {
 	for k, v := range fields {
 		switch k {
 		// logrus.WithError adds a field with name error.
-		case "error": fallthrough
+		case "error":
+			fallthrough
 		case "err":
 			// Record details of the error
 			if v, ok := v.(error); ok {

kafkahook/kafkahook_test.go

@@ -6,7 +6,6 @@ import (
 	"fmt"
 	"io/ioutil"
 	"net/http/httptest"
-	"path"
 	"strings"
 	"testing"
 
@@ -60,8 +59,11 @@ func (s *KafkaHookTests) TestKafkaHookINFO(c *C) {
 	c.Assert(req["message"], Equals, "this is a test")
 	c.Assert(req["context"], Equals, nil)
 	c.Assert(req["logLevel"], Equals, "INFO")
-	c.Assert(path.Base(req["filename"].(string)), Equals, "kafkahook_test.go")
-	c.Assert(strings.Contains(req["funcName"].(string), "TestKafkaHookINFO"), Equals, true)
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/kafkahook/kafkahook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"].(string), Equals,
+		"kafkahook_test.(*KafkaHookTests).TestKafkaHookINFO")
 }
 
 func (s *KafkaHookTests) TestKafkaHookExported(c *C) {
@@ -73,8 +75,11 @@ func (s *KafkaHookTests) TestKafkaHookExported(c *C) {
 	c.Assert(req["message"], Equals, "this is a test")
 	c.Assert(req["context"], Equals, nil)
 	c.Assert(req["logLevel"], Equals, "INFO")
-	c.Assert(path.Base(req["filename"].(string)), Equals, "kafkahook_test.go")
-	c.Assert(strings.Contains(req["funcName"].(string), "TestKafkaHookExported"), Equals, true)
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/kafkahook/kafkahook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"].(string), Equals,
+		"kafkahook_test.(*KafkaHookTests).TestKafkaHookExported")
 }
 
 func (s *KafkaHookTests) TestKafkaHookContext(c *C) {
@@ -87,10 +92,13 @@ func (s *KafkaHookTests) TestKafkaHookContext(c *C) {
 
 	req := GetMsg(s.producer)
 	c.Assert(req["message"], Equals, "this is a test")
-	c.Assert(req["lineno"], Equals, float64(86))
+	c.Assert(req["lineno"], Equals, float64(91))
 	c.Assert(req["logLevel"], Equals, "ERROR")
-	c.Assert(path.Base(req["filename"].(string)), Equals, "kafkahook_test.go")
-	c.Assert(strings.Contains(req["funcName"].(string), "TestKafkaHookContext"), Equals, true)
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/kafkahook/kafkahook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"].(string), Equals,
+		"kafkahook_test.(*KafkaHookTests).TestKafkaHookContext")
 
 	context := req["context"].(map[string]interface{})
 	c.Assert(context["http"].(map[string]interface{})["request"], Equals, "http://localhost")
@@ -148,9 +156,11 @@ func (s *KafkaHookTests) TestFromErr(c *C) {
 	s.log.WithFields(errors.ToLogrus(err)).Info("Info Called")
 
 	req := GetMsg(s.producer)
-	c.Assert(path.Base(req["filename"].(string)), Equals, "kafkahook_test.go")
-	c.Assert(req["lineno"], Equals, float64(146))
-	c.Assert(req["funcName"], Equals, "TestFromErr()")
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/kafkahook/kafkahook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["lineno"], Equals, float64(154))
+	c.Assert(req["funcName"], Equals, "kafkahook_test.(*KafkaHookTests).TestFromErr")
 	c.Assert(req["excType"], Equals, "*errors.fundamental")
 	c.Assert(req["excValue"], Equals, "bar: foo")
 	c.Assert(strings.Contains(req["excText"].(string), "(*KafkaHookTests).TestFromErr"), Equals, true)

levelfilter/levelfilter.go

@@ -3,7 +3,7 @@ package levelfilter
 import "github.com/sirupsen/logrus"
 
 type LevelFilter struct {
-	hook logrus.Hook
+	hook   logrus.Hook
 	levels []logrus.Level
 }
 
@@ -16,7 +16,7 @@ func New(hook logrus.Hook, level logrus.Level) *LevelFilter {
 	}
 
 	return &LevelFilter{
-		hook: hook,
+		hook:   hook,
 		levels: levels,
 	}
 }

levelfilter/levelfilter_test.go

@@ -1,11 +1,18 @@
 package levelfilter
 
 import (
+	"encoding/json"
 	"fmt"
+	"io/ioutil"
 	"testing"
 
+	"github.com/Shopify/sarama"
+	"github.com/Shopify/sarama/mocks"
+	"github.com/mailgun/logrus-hooks/kafkahook"
+	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 	. "gopkg.in/check.v1"
+	"strings"
 )
 
 func Test(t *testing.T) { TestingT(t) }
@@ -23,42 +30,41 @@ func (s *LevelFilterSuite) TestLevels(c *C) {
 		filtered []logrus.Level
 	}{
 		0: {
-		original: logrus.AllLevels,
-		level:    logrus.PanicLevel,
-		filtered: []logrus.Level{logrus.PanicLevel},
-	},
-		1: {
-		original: logrus.AllLevels,
-		level:    logrus.FatalLevel,
-		filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel},
-	}, 2: {
-		original: logrus.AllLevels,
-		level:    logrus.ErrorLevel,
-		filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel},
-	}, 3: {
-		original: logrus.AllLevels,
-		level:    logrus.WarnLevel,
-		filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel},
-	}, 4: {
-		original: logrus.AllLevels,
-		level:    logrus.InfoLevel,
-		filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel, logrus.InfoLevel},
-	}, 5: {
-		original: logrus.AllLevels,
-		level:    logrus.DebugLevel,
-		filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel, logrus.InfoLevel, logrus.DebugLevel},
-	}, 6: {
-		// Original missing levels stay missing when filtered.
-		original: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel, logrus.InfoLevel, logrus.DebugLevel},
-		level:    logrus.InfoLevel,
-		filtered: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel, logrus.InfoLevel},
-	}, 7: {
-		// It is ok to specify a level missing in the original list for filtering.
-		original: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel, logrus.DebugLevel},
-		level:    logrus.InfoLevel,
-		filtered: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel},
-	}} {
-		fmt.Printf("Test case #%d", i)
+			original: logrus.AllLevels,
+			level:    logrus.PanicLevel,
+			filtered: []logrus.Level{logrus.PanicLevel},
+		}, 1: {
+			original: logrus.AllLevels,
+			level:    logrus.FatalLevel,
+			filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel},
+		}, 2: {
+			original: logrus.AllLevels,
+			level:    logrus.ErrorLevel,
+			filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel},
+		}, 3: {
+			original: logrus.AllLevels,
+			level:    logrus.WarnLevel,
+			filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel},
+		}, 4: {
+			original: logrus.AllLevels,
+			level:    logrus.InfoLevel,
+			filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel, logrus.InfoLevel},
+		}, 5: {
+			original: logrus.AllLevels,
+			level:    logrus.DebugLevel,
+			filtered: []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel, logrus.InfoLevel, logrus.DebugLevel},
+		}, 6: {
+			// Original missing levels stay missing when filtered.
+			original: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel, logrus.InfoLevel, logrus.DebugLevel},
+			level:    logrus.InfoLevel,
+			filtered: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel, logrus.InfoLevel},
+		}, 7: {
+			// It is ok to specify a level missing in the original list for filtering.
+			original: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel, logrus.DebugLevel},
+			level:    logrus.InfoLevel,
+			filtered: []logrus.Level{logrus.PanicLevel, logrus.WarnLevel},
+		}} {
+		fmt.Printf("Test case #%d\n", i)
 
 		fakeHook := newFakeHook(tc.original)
 		lf := New(fakeHook, tc.level)
@@ -85,8 +91,50 @@ func (s *LevelFilterSuite) TestFire(c *C) {
 	c.Assert(fakeHook.entries, DeepEquals, []*logrus.Entry{e1, e2, e3})
 }
 
+func (s *LevelFilterSuite) TestCallerInfoWithError(c *C) {
+	kafkaHook, msgGetter := newKafkaHook(c)
+	log := logrus.New()
+	log.Out = ioutil.Discard
+
+	lh := New(kafkaHook, logrus.InfoLevel)
+	log.Hooks.Add(lh)
+
+	err := errors.New("Kaboom!")
+
+	// When
+	log.WithError(err).Error("Error Called")
+
+	// Then
+	req := msgGetter()
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/levelfilter/levelfilter_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"], Equals,
+		"levelfilter.(*LevelFilterSuite).TestCallerInfoWithError")
+}
+
+func (s *LevelFilterSuite) TestCallerInfo(c *C) {
+	kafkaHook, msgGetter := newKafkaHook(c)
+	log := logrus.New()
+	log.Out = ioutil.Discard
+
+	lh := New(kafkaHook, logrus.InfoLevel)
+	log.Hooks.Add(lh)
+
+	// When
+	log.Info("Info Called")
+
+	// Then
+	req := msgGetter()
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/levelfilter/levelfilter_test.go"), Equals,
+		true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"].(string), Equals,
+		"levelfilter.(*LevelFilterSuite).TestCallerInfo")
+}
+
 type fakeHook struct {
-	levels []logrus.Level
+	levels  []logrus.Level
 	entries []*logrus.Entry
 }
 
@@ -102,3 +150,37 @@ func (h *fakeHook) Fire(entry *logrus.Entry) error {
 	h.entries = append(h.entries, entry)
 	return nil
 }
+
+func newKafkaHook(c *C) (logrus.Hook, func() map[string]interface{}) {
+	// Setup our AsyncProducer Mock.
+	saramaCfg := sarama.NewConfig()
+	saramaCfg.Producer.Return.Successes = true
+	prod := mocks.NewAsyncProducer(c, saramaCfg)
+	prod.ExpectInputAndSucceed()
+
+	// Create the kafka hook.
+	kafkaHook, err := kafkahook.New(kafkahook.Config{
+		Producer: prod,
+		Topic:    "test",
+	})
+	c.Assert(err, IsNil)
+
+	// Create message getter.
+	msgGetter := func() map[string]interface{} {
+		return getMsg(prod)
+	}
+
+	return kafkaHook, msgGetter
+}
+
+func getMsg(producer *mocks.AsyncProducer) map[string]interface{} {
+	var result map[string]interface{}
+	msg := <-producer.Successes()
+	buf, _ := msg.Value.Encode()
+
+	fmt.Printf("%s\n", buf)
+	if err := json.Unmarshal(buf, &result); err != nil {
+		fmt.Printf("json.Unmarshal() error: %s\n", err)
+	}
+	return result
+}

udploghook/udploghook_test.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"io/ioutil"
 	"net/http/httptest"
-	"path"
 	"strings"
 	"testing"
 
@@ -54,8 +53,11 @@ func (s *UDPLogHookTests) TestUDPHookINFO(c *C) {
 	c.Assert(req["message"], Equals, "this is a test")
 	c.Assert(req["context"], Equals, nil)
 	c.Assert(req["logLevel"], Equals, "INFO")
-	c.Assert(path.Base(req["filename"].(string)), Equals, "udploghook_test.go")
-	c.Assert(strings.Contains(req["funcName"].(string), "TestUDPHookINFO"), Equals, true)
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/udploghook/udploghook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"].(string), Equals,
+		"udploghook_test.(*UDPLogHookTests).TestUDPHookINFO")
 }
 
 func (s *UDPLogHookTests) TestUDPHookExported(c *C) {
@@ -67,8 +69,11 @@ func (s *UDPLogHookTests) TestUDPHookExported(c *C) {
 	c.Assert(req["message"], Equals, "this is a test")
 	c.Assert(req["context"], Equals, nil)
 	c.Assert(req["logLevel"], Equals, "INFO")
-	c.Assert(path.Base(req["filename"].(string)), Equals, "udploghook_test.go")
-	c.Assert(strings.Contains(req["funcName"].(string), "TestUDPHookExported"), Equals, true)
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/udploghook/udploghook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"].(string), Equals,
+		"udploghook_test.(*UDPLogHookTests).TestUDPHookExported")
 }
 
 func (s *UDPLogHookTests) TestUDPHookContext(c *C) {
@@ -82,8 +87,11 @@ func (s *UDPLogHookTests) TestUDPHookContext(c *C) {
 	req := s.server.GetRequest()
 	c.Assert(req["message"], Equals, "this is a test")
 	c.Assert(req["logLevel"], Equals, "ERROR")
-	c.Assert(path.Base(req["filename"].(string)), Equals, "udploghook_test.go")
-	c.Assert(strings.Contains(req["funcName"].(string), "TestUDPHookContext"), Equals, true)
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/udploghook/udploghook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["funcName"].(string), Equals,
+		"udploghook_test.(*UDPLogHookTests).TestUDPHookContext")
 
 	context := req["context"].(map[string]interface{})
 	c.Assert(context["http"].(map[string]interface{})["request"], Equals, "http://localhost")
@@ -141,13 +149,16 @@ func (s *UDPLogHookTests) TestFromErr(c *C) {
 	s.log.WithFields(errors.ToLogrus(err)).Info("Info Called")
 
 	req := s.server.GetRequest()
-	c.Assert(path.Base(req["filename"].(string)), Equals, "udploghook_test.go")
-	c.Assert(req["lineno"], Equals, float64(139))
-	c.Assert(req["funcName"], Equals, "TestFromErr()")
+	c.Assert(strings.HasSuffix(req["filename"].(string),
+		"github.com/mailgun/logrus-hooks/udploghook/udploghook_test.go"),
+		Equals, true, Commentf(req["filename"].(string)))
+	c.Assert(req["lineno"], Equals, float64(147))
+	c.Assert(req["funcName"].(string), Equals,
+		"udploghook_test.(*UDPLogHookTests).TestFromErr")
 	c.Assert(req["excType"], Equals, "*errors.fundamental")
 	c.Assert(req["excValue"], Equals, "bar: foo")
 	c.Assert(strings.Contains(req["excText"].(string), "(*UDPLogHookTests).TestFromErr"), Equals, true)
-	c.Assert(strings.Contains(req["excText"].(string), "github.com/mailgun/logrus-hooks/udploghook/udploghook_test.go:139"), Equals, true)
+	c.Assert(strings.Contains(req["excText"].(string), "github.com/mailgun/logrus-hooks/udploghook/udploghook_test.go:147"), Equals, true)
 }
 
 func (s *UDPLogHookTests) TestTIDAsString(c *C) {