diff --git a/caller.go b/caller.go new file mode 100644 index 0000000..9179a94 --- /dev/null +++ b/caller.go @@ -0,0 +1,77 @@ +package logger + +import ( + "runtime" + "strings" + "sync" +) + +var ( + + // qualified package name, cached at first use + goLoggerPackage string + + // Positions in the call stack when tracing to report the calling method + minimumCallerDepth int + + // Used for caller information initialisation + callerInitOnce sync.Once +) + +const ( + maximumCallerDepth int = 25 + knownGoLoggerFrames int = 4 +) + +// getCaller retrieves the name of the first non-go-logger calling function +func getCaller() *runtime.Frame { + // cache this package's fully-qualified name + callerInitOnce.Do(func() { + pcs := make([]uintptr, maximumCallerDepth) + _ = runtime.Callers(0, pcs) + + // dynamic get the package name and the minimum caller depth + for i := 0; i < maximumCallerDepth; i++ { + funcName := runtime.FuncForPC(pcs[i]).Name() + if strings.Contains(funcName, "getCaller") { + goLoggerPackage = getPackageName(funcName) + break + } + } + + minimumCallerDepth = knownGoLoggerFrames + }) + + // Restrict the lookback frames to avoid runaway lookups + pcs := make([]uintptr, maximumCallerDepth) + depth := runtime.Callers(minimumCallerDepth, pcs) + frames := runtime.CallersFrames(pcs[:depth]) + + for f, again := frames.Next(); again; f, again = frames.Next() { + pkg := getPackageName(f.Function) + + // If the caller isn't part of this package, we're done + if pkg != goLoggerPackage { + return &f //nolint:scopelint + } + } + + // if we got here, we failed to find the caller's context + return nil +} + +// getPackageName reduces a fully qualified function name to the package name +// There really ought to be to be a better way... +func getPackageName(f string) string { + for { + lastPeriod := strings.LastIndex(f, ".") + lastSlash := strings.LastIndex(f, "/") + if lastPeriod > lastSlash { + f = f[:lastPeriod] + } else { + break + } + } + + return f +} diff --git a/entry.go b/entry.go index 8fa0b2d..e595633 100644 --- a/entry.go +++ b/entry.go @@ -1,91 +1,99 @@ package logger import ( - "runtime" - "strings" - "sync" + "context" + + "github.com/sirupsen/logrus" ) // Entry represents a logging entry and all supported method we use -type Entry interface { - Debugf(format string, args ...interface{}) - Debug(args ...interface{}) - Infof(format string, args ...interface{}) - Info(args ...interface{}) - Warnf(format string, args ...interface{}) - Warn(args ...interface{}) - Errorf(format string, args ...interface{}) - Error(args ...interface{}) - Fatalf(format string, args ...interface{}) - Fatal(args ...interface{}) +type Entry struct { + logger *Logger + fields Fields + context context.Context } -var ( +// WithError is a convenience wrapper for WithField("error", err) +func (e *Entry) WithError(err error) *Entry { + return e.WithField(errorKey, err) +} - // qualified package name, cached at first use - goLoggerPackage string +// WithField forwards a logging call with a field +func (e *Entry) WithField(key string, value interface{}) *Entry { + e.fields[key] = value + return e +} - // Positions in the call stack when tracing to report the calling method - minimumCallerDepth int +// WithFields forwards a logging call with fields +func (e *Entry) WithFields(fields Fields) *Entry { + for k, v := range fields { + e.fields[k] = v + } + return e +} - // Used for caller information initialisation - callerInitOnce sync.Once -) +// WithContext sets the context for the log-message. Useful when using hooks. +func (e *Entry) WithContext(ctx context.Context) *Entry { + e.context = ctx + return e +} -const ( - maximumCallerDepth int = 25 - knownGoLoggerFrames int = 4 -) +// Info forwards a logging call in the (format, args) format +func (e *Entry) Info(args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Info(args...) +} -// getCaller retrieves the name of the first non-go-logger calling function -func getCaller() *runtime.Frame { - // cache this package's fully-qualified name - callerInitOnce.Do(func() { - pcs := make([]uintptr, maximumCallerDepth) - _ = runtime.Callers(0, pcs) - - // dynamic get the package name and the minimum caller depth - for i := 0; i < maximumCallerDepth; i++ { - funcName := runtime.FuncForPC(pcs[i]).Name() - if strings.Contains(funcName, "getCaller") { - goLoggerPackage = getPackageName(funcName) - break - } - } - - minimumCallerDepth = knownGoLoggerFrames - }) - - // Restrict the lookback frames to avoid runaway lookups - pcs := make([]uintptr, maximumCallerDepth) - depth := runtime.Callers(minimumCallerDepth, pcs) - frames := runtime.CallersFrames(pcs[:depth]) - - for f, again := frames.Next(); again; f, again = frames.Next() { - pkg := getPackageName(f.Function) - - // If the caller isn't part of this package, we're done - if pkg != goLoggerPackage { - return &f //nolint:scopelint - } - } +// Infof forwards a logging call in the (format, args) format +func (e *Entry) Infof(format string, args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Infof(format, args...) +} - // if we got here, we failed to find the caller's context - return nil +// Error forwards an error logging call +func (e *Entry) Error(args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Error(args...) } -// getPackageName reduces a fully qualified function name to the package name -// There really ought to be to be a better way... -func getPackageName(f string) string { - for { - lastPeriod := strings.LastIndex(f, ".") - lastSlash := strings.LastIndex(f, "/") - if lastPeriod > lastSlash { - f = f[:lastPeriod] - } else { - break - } - } +// Errorf forwards an error logging call +func (e *Entry) Errorf(format string, args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Errorf(format, args...) +} + +// Debug forwards a debugging logging call +func (e *Entry) Debug(args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Debug(args...) +} + +// Debugf forwards a debugging logging call +func (e *Entry) Debugf(format string, args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Debugf(format, args...) +} + +// Warn forwards a warning logging call +func (e *Entry) Warn(args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Warn(args...) +} + +// Warnf forwards a warning logging call +func (e *Entry) Warnf(format string, args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Warnf(format, args...) +} + +// Fatal forwards a fatal logging call +func (e *Entry) Fatal(args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Fatal(args...) +} - return f +// Fatalf forwards a fatal logging call +func (e *Entry) Fatalf(format string, args ...interface{}) { + logrusFields := logrus.Fields(e.fields) + e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Fatalf(format, args...) } diff --git a/global_logger.go b/global_logger.go index 3a54182..bf401f4 100644 --- a/global_logger.go +++ b/global_logger.go @@ -18,22 +18,22 @@ func Global() *Logger { } // WithError is a convenience wrapper for WithField("err", err) -func WithError(err error) Entry { +func WithError(err error) *Entry { return globalLogger.WithError(err) } // WithField creates log entry using global logger -func WithField(key string, value interface{}) Entry { +func WithField(key string, value interface{}) *Entry { return globalLogger.WithField(key, value) } // WithFields creates log entry using global logger -func WithFields(fields Fields) Entry { +func WithFields(fields Fields) *Entry { return globalLogger.WithFields(fields) } // WithContext creates log entry using global logger -func WithContext(ctx context.Context) Entry { +func WithContext(ctx context.Context) *Entry { return globalLogger.WithContext(ctx) } diff --git a/global_logger_test.go b/global_logger_test.go index 4a4e877..6220180 100644 --- a/global_logger_test.go +++ b/global_logger_test.go @@ -2,6 +2,8 @@ package logger import ( "bytes" + "context" + "fmt" "testing" ) @@ -124,3 +126,70 @@ func TestGlobalLoggerConvenienveFunctions(t *testing.T) { Info("but now I will") assertLogEntryContains(t, buf, "msg", "but now I will") } + +func TestChainingSetup(t *testing.T) { + buf := &bytes.Buffer{} + oldOutput := globalLogger.output + oldLevel := globalLogger.level + oldNowFunc := globalLogger.now + defer func() { + // bring global logger to original state after tests + ConfigureGlobalLogger(WithOutput(oldOutput), WithLevel(oldLevel), WithNowFunc(oldNowFunc)) + }() + ConfigureGlobalLogger(WithOutput(buf), WithLevel(LevelDebug), WithNowFunc(mockNowFunc), WithHookFunc(testHook)) + + ctx := context.WithValue(context.Background(), myCtxKey{}, "my-custom-ctx-value") + err := fmt.Errorf("some error") + + { + // Start with global WithField + WithField("foo", "bar").WithContext(ctx).WithFields(Fields{"baz": "quoo", "number": 42}).WithError(err).Infof("hello %s", "world") + b := buf.Bytes() // get bytes for multiple-reads + buf.Reset() // Prepare for next log message + + assertLogEntryContains(t, bytes.NewReader(b), "msg", "hello world") + assertLogEntryContains(t, bytes.NewReader(b), "foo", "bar") + assertLogEntryContains(t, bytes.NewReader(b), "my-custom-log-key", "my-custom-ctx-value") + assertLogEntryContains(t, bytes.NewReader(b), "baz", "quoo") + assertLogEntryContains(t, bytes.NewReader(b), "number", float64(42)) + } + + { + // Start with global WithFields + WithFields(Fields{"baz": "quoo", "number": 42}).WithField("foo", "bar").WithContext(ctx).WithError(err).Infof("hello %s", "world") + b := buf.Bytes() // get bytes for multiple-reads + buf.Reset() // Prepare for next log message + + assertLogEntryContains(t, bytes.NewReader(b), "msg", "hello world") + assertLogEntryContains(t, bytes.NewReader(b), "foo", "bar") + assertLogEntryContains(t, bytes.NewReader(b), "my-custom-log-key", "my-custom-ctx-value") + assertLogEntryContains(t, bytes.NewReader(b), "baz", "quoo") + assertLogEntryContains(t, bytes.NewReader(b), "number", float64(42)) + } + + { + // Start with global WithError + WithError(err).WithFields(Fields{"baz": "quoo", "number": 42}).WithField("foo", "bar").WithContext(ctx).Infof("hello %s", "world") + b := buf.Bytes() // get bytes for multiple-reads + buf.Reset() // Prepare for next log message + + assertLogEntryContains(t, bytes.NewReader(b), "msg", "hello world") + assertLogEntryContains(t, bytes.NewReader(b), "foo", "bar") + assertLogEntryContains(t, bytes.NewReader(b), "my-custom-log-key", "my-custom-ctx-value") + assertLogEntryContains(t, bytes.NewReader(b), "baz", "quoo") + assertLogEntryContains(t, bytes.NewReader(b), "number", float64(42)) + } + + { + // Start with global WithContext + WithContext(ctx).WithError(err).WithFields(Fields{"baz": "quoo", "number": 42}).WithField("foo", "bar").Infof("hello %s", "world") + b := buf.Bytes() // get bytes for multiple-reads + buf.Reset() // Prepare for next log message + + assertLogEntryContains(t, bytes.NewReader(b), "msg", "hello world") + assertLogEntryContains(t, bytes.NewReader(b), "foo", "bar") + assertLogEntryContains(t, bytes.NewReader(b), "my-custom-log-key", "my-custom-ctx-value") + assertLogEntryContains(t, bytes.NewReader(b), "baz", "quoo") + assertLogEntryContains(t, bytes.NewReader(b), "number", float64(42)) + } +} diff --git a/hooks.go b/hooks.go index c64b000..5a5efb2 100644 --- a/hooks.go +++ b/hooks.go @@ -35,17 +35,17 @@ type HookEntry struct { Context context.Context } -type customHook struct { +type logrusHook struct { hook Hook } // Levels implements the logrus.Hook interface. -func (h *customHook) Levels() []logrus.Level { +func (h *logrusHook) Levels() []logrus.Level { return logrus.AllLevels } // Fire implements the logrus.Hook interface. -func (h *customHook) Fire(entry *logrus.Entry) error { +func (h *logrusHook) Fire(entry *logrus.Entry) error { // Provide all entry-data so the hook can mutate them. hookEntry := &HookEntry{ Data: Fields(entry.Data), diff --git a/logger.go b/logger.go index cd29427..f33258a 100644 --- a/logger.go +++ b/logger.go @@ -48,36 +48,37 @@ func New(opts ...LoggerOption) *Logger { return logger } -func (logger *Logger) entry() Entry { - fields := logrus.Fields{} +func (logger *Logger) entry() *Entry { + fields := Fields{} if logger.reportCaller { frame := getCaller() fields["file"] = fmt.Sprintf("%s:%v", frame.File, frame.Line) fields["function"] = frame.Function } - return logger.logrusLogger.WithTime(logger.now()).WithFields(fields) + + return &Entry{logger: logger, fields: fields} } const errorKey = "error" // WithError is a convenience wrapper for WithField("error", err) -func (logger *Logger) WithError(err error) Entry { +func (logger *Logger) WithError(err error) *Entry { return logger.WithField(errorKey, err) } // WithField forwards a logging call with a field -func (logger *Logger) WithField(key string, value interface{}) Entry { - return logger.logrusLogger.WithTime(logger.now()).WithField(key, value) +func (logger *Logger) WithField(key string, value interface{}) *Entry { + return logger.entry().WithField(key, value) } // WithFields forwards a logging call with fields -func (logger *Logger) WithFields(fields Fields) Entry { - return logger.logrusLogger.WithTime(logger.now()).WithFields(logrus.Fields(fields)) +func (logger *Logger) WithFields(fields Fields) *Entry { + return logger.entry().WithFields(fields) } // WithContext forwards a logging call with fields -func (logger *Logger) WithContext(ctx context.Context) Entry { - return logger.logrusLogger.WithTime(logger.now()).WithContext(ctx) +func (logger *Logger) WithContext(ctx context.Context) *Entry { + return logger.entry().WithContext(ctx) } // OutputHandler returns logger output handler diff --git a/logger_test.go b/logger_test.go index 356b4b6..f51110d 100644 --- a/logger_test.go +++ b/logger_test.go @@ -12,6 +12,7 @@ import ( ) func assertLogEntryContains(t *testing.T, logReader io.Reader, key string, expectedValue interface{}) { + t.Helper() log := make(map[string]interface{}) err := json.NewDecoder(logReader).Decode(&log) if err != nil { @@ -38,6 +39,7 @@ func assertLogEntryContains(t *testing.T, logReader io.Reader, key string, expec } func assertLogEntryHasKey(t *testing.T, logReader io.Reader, key string) { + t.Helper() log := make(map[string]interface{}) err := json.NewDecoder(logReader).Decode(&log) if err != nil { @@ -50,6 +52,7 @@ func assertLogEntryHasKey(t *testing.T, logReader io.Reader, key string) { } func assertLogEntryDoesNotHaveKey(t *testing.T, logReader io.Reader, key string) { + t.Helper() log := make(map[string]interface{}) err := json.NewDecoder(logReader).Decode(&log) if err != nil { @@ -345,12 +348,28 @@ func TestHookWithoutContext(t *testing.T) { assertLogEntryDoesNotHaveKey(t, tee, "my-custom-log-key") } -func TestHookWithContext2(t *testing.T) { - ctx := context.WithValue(context.Background(), myCtxKey{}, "my-custom-ctx-value") +func TestReuseEntry(t *testing.T) { + builder := &strings.Builder{} + logger := New(WithOutput(builder), WithLevel(LevelInfo)) + withFields := logger.WithField("foo", "bar") + withFields.Info("quoo") + withFields.Error("baz") - buf := &bytes.Buffer{} - tee := io.TeeReader(buf, buf) - logger := New(WithOutput(buf), WithHookFunc(testHook)) - logger.WithContext(ctx).Error("foobar") - assertLogEntryContains(t, tee, "my-custom-log-key", "my-custom-ctx-value") + str := builder.String() + lines := strings.Split(str, "\n") + if len(lines) != 3 { + // Info + Error + empty newline + t.Fatalf("expected %d lines, got %d", 3, len(lines)) + } + if lines[2] != "" { + t.Fatalf("expected last line to be empty, got %s", lines[2]) + } + + assertLogEntryContains(t, strings.NewReader(lines[0]), "foo", "bar") + assertLogEntryContains(t, strings.NewReader(lines[0]), "msg", "quoo") + assertLogEntryContains(t, strings.NewReader(lines[0]), "level", "info") + + assertLogEntryContains(t, strings.NewReader(lines[1]), "foo", "bar") + assertLogEntryContains(t, strings.NewReader(lines[1]), "msg", "baz") + assertLogEntryContains(t, strings.NewReader(lines[1]), "level", "error") } diff --git a/opts.go b/opts.go index 5f44ff8..78957c6 100644 --- a/opts.go +++ b/opts.go @@ -64,6 +64,6 @@ func WithHookFunc(hook HookFunc) LoggerOption { // WithHook allows for connecting a hook to the logger, which will be triggered on all log-entries. func WithHook(hook Hook) LoggerOption { return LoggerOptionFunc(func(l *Logger) { - l.logrusLogger.Hooks.Add(&customHook{hook: hook}) + l.logrusLogger.Hooks.Add(&logrusHook{hook: hook}) }) }