Add filtered leveled logging and error promotion

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 }
+}

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

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.

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