From cf434f53375af17d398efe1a2657f9d34c16e038 Mon Sep 17 00:00:00 2001 From: Kyle Woodlock Date: Thu, 5 May 2016 19:26:25 -0400 Subject: [PATCH] Add filtered leveled logging and error promotion Adds a couple new options to levels.Levels, including: - FilterLogLevel: specify the minimum log level you want to see actually hit your logs. Anything below this will be discarded in as cheap a fashion as possible. Defaults to Debug, that is, showing everything. - PromoteErrors: if true, a log line that contains an error will be promoted to a higher log level, potentially bypassing the FilterLogLevel. This allows a developer to do a bunch of debug logging of function call results and, in production, not see any of them unless the log line actually has an error. By default this flag is set to false. - ErrorKey: the key in the context where we should search for the existence of an error. If we find a `nil` value at that location, or if that is not a key in the context, we treat it as not having an error. Defaults to "error". - PromoteErrorToLogLevel: the log level that error logs should be promoted to. Promotion only occurs if the log level explicitly specified is lower than this value, so if you log at critical level and include an error, it doesn't get downgraded. Default for this is Error. Creates an ordered enumeration of LogLevels from Debug up to Crit, so users can specify the FilterLogLevel and PromoteErrorToLogLevel options noted above. To detect the presence of errors in the context, I had to add a HasValue utility method on log.Context. I would have preferred that this method not be exported at all, but because levels and log are different packages, it is not visible to be used in levels unless it is exported. --- log/levels/levels.go | 132 ++++++++++++++++++++++++++++++++++++-- log/levels/levels_test.go | 93 +++++++++++++++++++++++++++ log/log.go | 22 +++++++ log/log_test.go | 32 +++++++++ 4 files changed, 274 insertions(+), 5 deletions(-) diff --git a/log/levels/levels.go b/log/levels/levels.go index da6b681b1..c3fa14d7a 100644 --- a/log/levels/levels.go +++ b/log/levels/levels.go @@ -29,8 +29,54 @@ type Levels struct { warnValue string errorValue string critValue string + + // FilterLogLevel is an option allowing logs below a certain level to be + // discarded rather than logged. For example, a consumer may set LogLevel + // to levels.Warn, and any logs to Debug or Info would become no-ops. + filterLogLevel LogLevel + + // Promote errors + promoteErrors bool + errorKey string + promoteErrorToLevel LogLevel +} + +// levelCommittedLogger embeds a log level that the user has selected and prepends +// the associated level string as a prefix to every log line. Log level may be +// affected by error promotion; and log lines may be suppressed based on the value +// of FilterLogLevel. +type levelCommittedLogger struct { + levels Levels + + committedLevel LogLevel } +type LogLevel int + +var ( + // Debug should be used for information that is useful to developers for + // forensic purposes but is not useful information for everyday operations. + Debug LogLevel = 0 + + // Info should be used for information that is useful and actionable in + // production operations when everything is running smoothly. + Info LogLevel = 1 + + // Warn should be used to note that the system is still performing its job + // successfully, but a notable expectation for proper operation was not + // met. If left untreated, warnings could eventually escalate into errors. + Warn LogLevel = 2 + + // Error should be used to flag when the system has failed to uphold its + // operational contract in some way, and the failure was not recoverable. + Error LogLevel = 3 + + // Crit should only be used when an error occurs that is so catastrophic, + // the system is going to immediately become unavailable for any future + // operations until the problem is repaired. + Crit LogLevel = 4 +) + // New creates a new leveled logger, wrapping the passed logger. func New(logger log.Logger, options ...Option) Levels { l := Levels{ @@ -42,6 +88,12 @@ func New(logger log.Logger, options ...Option) Levels { warnValue: "warn", errorValue: "error", critValue: "crit", + + filterLogLevel: Debug, + + promoteErrors: false, + errorKey: "error", + promoteErrorToLevel: Error, } for _, option := range options { option(&l) @@ -59,32 +111,77 @@ func (l Levels) With(keyvals ...interface{}) Levels { warnValue: l.warnValue, errorValue: l.errorValue, critValue: l.critValue, + + filterLogLevel: l.filterLogLevel, + + promoteErrors: l.promoteErrors, + errorKey: l.errorKey, + promoteErrorToLevel: l.promoteErrorToLevel, + } +} + +func (l levelCommittedLogger) With(keyvals ...interface{}) levelCommittedLogger { + return levelCommittedLogger{ + levels: l.levels.With(keyvals...), + committedLevel: l.committedLevel, } } +func (l levelCommittedLogger) Log(keyvals ...interface{}) error { + lvl, ctx := l.committedLevel, l.levels.ctx.With(keyvals...) + + // Check whether the log level should be promoted because of an error. + if l.levels.promoteErrors && lvl < l.levels.promoteErrorToLevel && ctx.HasValue(l.levels.errorKey) { + lvl = l.levels.promoteErrorToLevel + } + + // Suppress logging if the level of this log line is below the minimum + // log level we want to see. + if lvl < l.levels.filterLogLevel { + return nil + } + + // Get the string associated with the current logLevel. + var levelValue string + switch lvl { + case Debug: + levelValue = l.levels.debugValue + case Info: + levelValue = l.levels.infoValue + case Warn: + levelValue = l.levels.warnValue + case Error: + levelValue = l.levels.errorValue + case Crit: + levelValue = l.levels.critValue + } + + return ctx.WithPrefix(l.levels.levelKey, levelValue).Log() +} + // Debug returns a debug level logger. func (l Levels) Debug() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.debugValue) + return levelCommittedLogger{l, Debug} } // Info returns an info level logger. func (l Levels) Info() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.infoValue) + return levelCommittedLogger{l, Info} } // Warn returns a warning level logger. func (l Levels) Warn() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.warnValue) + return levelCommittedLogger{l, Warn} } // Error returns an error level logger. func (l Levels) Error() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.errorValue) + return levelCommittedLogger{l, Error} } // Crit returns a critical level logger. func (l Levels) Crit() log.Logger { - return l.ctx.WithPrefix(l.levelKey, l.critValue) + return levelCommittedLogger{l, Crit} } // Option sets a parameter for leveled loggers. @@ -125,3 +222,28 @@ func ErrorValue(value string) Option { func CritValue(value string) Option { return func(l *Levels) { l.critValue = value } } + +// FilterLogLevel sets the value for the minimum log level that will be +// printed by the logger. By default, the value is levels.Debug. +func FilterLogLevel(value LogLevel) Option { + return func(l *Levels) { l.filterLogLevel = value } +} + +// PromoteErrors sets whether log lines with errors will be promoted to a +// higher log level. By default, the value is false. +func PromoteErrors(value bool) Option { + return func(l *Levels) { l.promoteErrors = value } +} + +// ErrorKey sets the key where errors will be stored in the log line. This +// is used if PromoteErrors is set to determine whether a log line should +// be promoted. By default, the value is "error". +func ErrorKey(value string) Option { + return func(l *Levels) { l.errorKey = value } +} + +// PromoteErrorToLevel sets the log level that log lines containing errors +// should be promoted to. By default, the value is levels.Error. +func PromoteErrorToLevel(value LogLevel) Option { + return func(l *Levels) { l.promoteErrorToLevel = value } +} diff --git a/log/levels/levels_test.go b/log/levels/levels_test.go index 270963cb2..6beda66c5 100644 --- a/log/levels/levels_test.go +++ b/log/levels/levels_test.go @@ -54,6 +54,99 @@ func TestModifiedLevels(t *testing.T) { } } +func TestFilteredLevels(t *testing.T) { + buf := bytes.Buffer{} + logger := levels.New( + log.NewLogfmtLogger(&buf), + levels.FilterLogLevel(levels.Warn), + ) + + debugValuerCalled := false + logger.Debug().Log("msg", "a debug log", "other", log.Valuer(func() interface{} { debugValuerCalled = true; return 42 })) + if want, have := "", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + if debugValuerCalled { + t.Error("Evaluated valuer in a filtered debug log unnecessarily") + } + + buf.Reset() + infoValuerCalled := false + logger.Info().Log("msg", "an info log", "other", log.Valuer(func() interface{} { debugValuerCalled = true; return 42 })) + if want, have := "", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + if infoValuerCalled { + t.Error("Evaluated valuer in a filtered debug log unnecessarily") + } + + buf.Reset() + logger.Warn().Log("msg", "a warning log") + if want, have := "level=warn msg=\"a warning log\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + logger.Error().Log("msg", "an error log") + if want, have := "level=error msg=\"an error log\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + logger.Crit().Log("msg", "a critical log") + if want, have := "level=crit msg=\"a critical log\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + +func TestErrorPromotion(t *testing.T) { + buf := bytes.Buffer{} + logger := levels.New( + log.NewLogfmtLogger(&buf), + levels.PromoteErrors(true), + levels.FilterLogLevel(levels.Error), + ) + // Should promote past filtering. + logger.Debug().Log("error", "some error") + if want, have := "level=error error=\"some error\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + // Should not promote if log level is already higher than the error level. + buf.Reset() + logger.Crit().Log("error", "some error") + if want, have := "level=crit error=\"some error\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + logger = levels.New( + log.NewLogfmtLogger(&buf), + levels.PromoteErrors(true), + levels.PromoteErrorToLevel(levels.Warn), + levels.ErrorKey("err"), + ) + // Should respect the configured ErrorKey + logger.Debug().Log("error", "some error") + if want, have := "level=debug error=\"some error\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + // Should promote to the configured level + buf.Reset() + logger.Debug().Log("err", "some error") + if want, have := "level=warn err=\"some error\"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + // Should treat nil errors as not an error + buf.Reset() + logger.Debug().Log("err", nil) + if want, have := "level=debug err=null\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + func ExampleLevels() { logger := levels.New(log.NewLogfmtLogger(os.Stdout)) logger.Debug().Log("msg", "hello") diff --git a/log/log.go b/log/log.go index 25e76cb74..f31eb2b0e 100644 --- a/log/log.go +++ b/log/log.go @@ -140,6 +140,28 @@ func (l *Context) WithPrefix(keyvals ...interface{}) *Context { } } +// HasValue returns true if any key (even index) is equal to the argument, and +// the value associated with that key (subsequent odd index) is not nil or +// ErrMissingValue. +func (l *Context) HasValue(key interface{}) bool { + kvs := l.keyvals + // Loop over all the full key/value pairs. If there is a dangling key + // at the end of the list, ignore it: it can't have a value. + for i, j, kvl := 0, 1, len(kvs); j < kvl; i, j = i+2, j+2 { + if kvs[i] == key { + // We found a matching key, so check that the value + // is non-nil, potentially evaluating it if it is a + // Valuer. + val := kvs[j] + if vv, isValuer := val.(Valuer); isValuer { + val = vv() + } + return val != nil && val != ErrMissingValue + } + } + return false +} + // LoggerFunc is an adapter to allow use of ordinary functions as Loggers. If // f is a function with the appropriate signature, LoggerFunc(f) is a Logger // object that calls f. diff --git a/log/log_test.go b/log/log_test.go index 7cd084411..9231bc169 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -163,6 +163,38 @@ func TestWithConcurrent(t *testing.T) { } } +func TestHasValue(t *testing.T) { + expensiveCallWasMade := false + + logger := log.NewContext(log.LoggerFunc(func(kv ...interface{}) error { return nil })). + With( + "foo", 42, + "bar", nil, + "baz", log.Valuer(func() interface{} { return "happy" }), + "qux", log.Valuer(func() interface{} { return nil }), + "corge", log.Valuer(func() interface{} { expensiveCallWasMade = true; return nil }), + "grault") + + tests := map[string]bool{ + "foo": true, // Has a value + "bar": false, // Value is nil + "baz": true, // Has a valuer that evaluates to a value + "qux": false, // Has a valuer that evaluates to nil + "grault": false, // Maps to ErrMissingValue + "garply": false, // Key isn't in the context at all + } + + for key, want := range tests { + if have := logger.HasValue(key); want != have { + t.Errorf("\nkey: %s, want: %v, have: %v", key, want, have) + } + } + + if expensiveCallWasMade { + t.Error("\nValuer was evaluated unnecessarily") + } +} + func BenchmarkDiscard(b *testing.B) { logger := log.NewNopLogger() b.ReportAllocs()