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()