diff --git a/hooks/caller/caller_hook.go b/hooks/caller/caller_hook.go new file mode 100644 index 0000000..ac7b56f --- /dev/null +++ b/hooks/caller/caller_hook.go @@ -0,0 +1,174 @@ +package caller + +import ( + "fmt" + "log" + "path" + "runtime" + "strings" + + "github.com/sirupsen/logrus" +) + +// refer import "log" +const ( + Ldate = 1 << iota // the date in the local time zone: 2009/01/23 + Ltime // the time in the local time zone: 01:23:23 + Lmicroseconds // microsecond resolution: 01:23:23.123123. assumes Ltime. + Llongfile // full file name and line number: /a/b/c/d.go:23 + Lshortfile // final file name element and line number: d.go:23. overrides Llongfile + LUTC // if Ldate or Ltime is set, use UTC rather than the local time zone + LstdFlags = Ldate | Ltime // initial values for the standard logger +) + +// CallerHook adds caller information to log entries. +// +// Sample usage: +// logrus.AddHook(caller.NewHook(&caller.CallerHookOptions{ +// Field: "src", +// Flags: log.Lshortfile, +// })) +// logrus.SetFormatter(&logrus.JSONFormatter{}) +// logrus.Info("Test log") +// // time="2018-05-10T00:00:00-00:00" level=info msg="Test log" file="main.go:66" + +type CallerHook struct { + CallerHookOptions *CallerHookOptions +} + +// NewHook creates a new caller hook with options. If options are nil or unspecified, options.Field defaults to "src" +// and options.Flags defaults to log.Llongfile +func NewHook(options *CallerHookOptions) *CallerHook { + //old + // Set default caller field to "src" + if options.Field == "" { + options.Field = "src" + } + // new + if options.FileAlias == "" { + options.FileAlias = "file" + } + if options.LineAlias == "" { + options.LineAlias = "line" + } + // Set default caller flag to Std logger log.Llongfile + if options.Flags == 0 { + // old + //options.Flags = log.Llongfile + // new + options.Flags = log.Lshortfile + } + return &CallerHook{options} +} + +// CallerHookOptions stores caller hook options +type CallerHookOptions struct { + // new + FileAlias string //default:file + EnableFile bool + LineAlias string //default:line + EnableLine bool + // old + // Field to display caller info in + Field string + DisabledField bool + // Stores the flags + Flags int + + //fileNmar + //Line Nmae +} + +// HasFlag returns true if the report caller options contains the specified flag +func (options *CallerHookOptions) HasFlag(flag int) bool { + return options.Flags&flag != 0 +} + +func (hook *CallerHook) Fire(entry *logrus.Entry) error { + + // new + // 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) + if hook.CallerHookOptions.HasFlag(log.Lshortfile) && !hook.CallerHookOptions.HasFlag(log.Llongfile) { + file = path.Base(file) + } + if !hook.CallerHookOptions.DisabledField { + entry.Data[hook.CallerHookOptions.Field] = fmt.Sprintf("%s:%d", file, line) + } + if hook.CallerHookOptions.EnableFile { + entry.Data[hook.CallerHookOptions.FileAlias] = file + } + if hook.CallerHookOptions.EnableLine { + entry.Data[hook.CallerHookOptions.LineAlias] = line + } + + // old + //entry.Data[hook.CallerHookOptions.Field] = hook.callerInfo(entry.CallerFrames() + 1) // add 1 for this frame + //entry.Data[hook.CallerHookOptions.Field] = hook.callerInfo(1) // add 1 for this frame + + return nil +} + +func (hook *CallerHook) Levels() []logrus.Level { + return []logrus.Level{ + logrus.PanicLevel, + logrus.FatalLevel, + logrus.ErrorLevel, + logrus.WarnLevel, + logrus.InfoLevel, + logrus.DebugLevel, + } +} + +//old +func (hook *CallerHook) callerInfo(skipFrames int) string { + // Follows output of Std logger + _, file, line, ok := runtime.Caller(skipFrames) + if !ok { + file = "???" + line = 0 + } else { + // check flags + if hook.CallerHookOptions.HasFlag(log.Lshortfile) && !hook.CallerHookOptions.HasFlag(log.Llongfile) { + file = path.Base(file) + } + } + return fmt.Sprintf("%s:%d", file, line) +} + +// 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 +} + +//new +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") +} diff --git a/hooks/caller/caller_hook_test.go b/hooks/caller/caller_hook_test.go new file mode 100644 index 0000000..1c7dff9 --- /dev/null +++ b/hooks/caller/caller_hook_test.go @@ -0,0 +1,178 @@ +package caller + +import ( + "bufio" + "bytes" + "encoding/json" + "fmt" + "log" + "sync" + "testing" + "time" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" +) + +type logJson struct { + Level string + Msg string + Time time.Time + Src string +} + +func TestCallerHook_ExportedInfo(t *testing.T) { + var buffer bytes.Buffer + // Caller hook + logrus.AddHook(NewHook(&CallerHookOptions{ + Field: "src", + Flags: log.Lshortfile, + })) + logrus.SetFormatter(&logrus.JSONFormatter{}) + logrus.SetOutput(&buffer) + + testCallerHookExportedInfo(t, &buffer, "Testing") + testCallerHookExportedInfo(t, &buffer, "Testing 2") + testCallerHookExportedInfo(t, &buffer, "Testing 3") + + // Test in goroutines + count := 50 + var wg sync.WaitGroup + for i := 0; i < count; i++ { + wg.Add(1) + go func(t *testing.T, wg *sync.WaitGroup, i int) { + defer wg.Done() + logrus.Info(fmt.Sprintf("Testing for race conditions %d", i)) + }(t, &wg, i) + } + // Wait for goroutines + wg.Wait() +} + +func testCallerHookExportedInfo(t *testing.T, buffer *bytes.Buffer, msg string) { + var j logJson + logrus.Info(msg) + scanner := bufio.NewScanner(buffer) + scanner.Scan() + line := scanner.Text() + assert.NoError(t, scanner.Err(), "Scanner error") + json.Unmarshal([]byte(line), &j) + assert.Equal(t, "caller_test.go:54", j.Src, "%v", j) + assert.Equal(t, msg, j.Msg, "%v", j) + assert.Equal(t, "info", j.Level, "%v", j) +} + +func TestCallerHook_ExportedEntryInfo(t *testing.T) { + var buffer bytes.Buffer + // Caller hook + logrus.AddHook(NewHook(&CallerHookOptions{ + Field: "src", + Flags: log.Lshortfile, + })) + logrus.SetFormatter(&logrus.JSONFormatter{}) + logrus.SetOutput(&buffer) + + testCallerHookExportedEntryInfo(t, &buffer, "Testing") + testCallerHookExportedEntryInfo(t, &buffer, "Testing 2") + testCallerHookExportedEntryInfo(t, &buffer, "Testing 3") + + // Test in goroutines + count := 50 + var wg sync.WaitGroup + for i := 0; i < count; i++ { + wg.Add(1) + go func(t *testing.T, wg *sync.WaitGroup, i int) { + defer wg.Done() + logrus.Info(fmt.Sprintf("Testing for race conditions %d", i)) + }(t, &wg, i) + } + // Wait for goroutines + wg.Wait() +} + +func testCallerHookExportedEntryInfo(t *testing.T, buffer *bytes.Buffer, msg string) { + var j logJson + logrus.WithField("testcaller", "testcaller value").Info(msg) + scanner := bufio.NewScanner(buffer) + scanner.Scan() + line := scanner.Text() + assert.NoError(t, scanner.Err(), "Scanner error") + json.Unmarshal([]byte(line), &j) + assert.Equal(t, "caller_test.go:95", j.Src, "%v", j) + assert.Equal(t, msg, j.Msg, "%v", j) + assert.Equal(t, "info", j.Level, "%v", j) +} + +func TestCallerHook_NewLoggerInfo(t *testing.T) { + var buffer bytes.Buffer + logr := logrus.New() + // Caller hook + logr.Hooks.Add(NewHook(&CallerHookOptions{ + Field: "src", + Flags: log.Lshortfile, + })) + logr.Formatter = &logrus.JSONFormatter{} + logr.Out = &buffer + + testCallerHookInfo(t, logr, "Testing") + testCallerHookInfo(t, logr, "Testing 2") + testCallerHookInfo(t, logr, "Testing 3") + + // Test in goroutines + count := 50 + var wg sync.WaitGroup + for i := 0; i < count; i++ { + wg.Add(1) + go func(t *testing.T, wg *sync.WaitGroup, logr *logrus.Logger, i int) { + defer wg.Done() + logr.Info(fmt.Sprintf("Testing for race conditions %d", i)) + }(t, &wg, logr, i) + } + // Wait for goroutines + wg.Wait() +} + +func TestCallerHook_LoggerInfo(t *testing.T) { + var buffer bytes.Buffer + logr := &logrus.Logger{ + Out: &buffer, + Formatter: new(logrus.JSONFormatter), + Hooks: make(logrus.LevelHooks), + Level: logrus.InfoLevel, + } + // Caller hook + logr.Hooks.Add(NewHook(&CallerHookOptions{ + Field: "src", + Flags: log.Lshortfile, + })) + + testCallerHookInfo(t, logr, "Testing") + testCallerHookInfo(t, logr, "Testing 2") + testCallerHookInfo(t, logr, "Testing 3") + + // Test in goroutines + count := 50 + var wg sync.WaitGroup + for i := 0; i < count; i++ { + wg.Add(1) + go func(t *testing.T, wg *sync.WaitGroup, logr *logrus.Logger, i int) { + defer wg.Done() + logr.Info(fmt.Sprintf("Testing for race conditions %d", i)) + }(t, &wg, logr, i) + } + // Wait for goroutines + wg.Wait() +} + +func testCallerHookInfo(t *testing.T, logr *logrus.Logger, msg string) { + var j logJson + logr.Info(msg) + scanner := bufio.NewScanner(logr.Out.(*bytes.Buffer)) + scanner.Scan() + line := scanner.Text() + assert.NoError(t, scanner.Err(), "Scanner error") + json.Unmarshal([]byte(line), &j) + assert.Equal(t, "caller_test.go:169", j.Src, "%v", j) + assert.Equal(t, msg, j.Msg, "%v", j) + assert.Equal(t, "info", j.Level, "%v", j) +}