Add filtered leveled logging and error promotion

[bishoprook]

Addresses #250

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.

[jmcgill0brightcove]

I would much rather see this as a distinct implementation of the Logger (or Levels) interface, than as a change to the behavior of Levels. Otherwise, systems that currently depend on kitlog behavior will be encouraged (or forced) to fork go-kit.

[bishoprook]

With the default options for filterLogLevel, promoteErrors, errorKey, and promoteErrorToLevel, there shouldn't be any changes to the behavior of go-kit/log or go-kit/log/levels... Can you give a specific instance of existing behavior that would be altered?

[bishoprook]

To be more verbose...

The Logger interface is very short:

type Logger interface {
    Log(keyvals ...interface{}) error
}

levelCommittedLogger implements the Log method at line 130 in this file, so it satisfies the log.Logger interface.

Let's look specifically at the levels.Debug case. Previously it returned a log.Logger, and it still does. Before this change, it returned l.ctx.WithPrefix(l.levelKey, l.debugValue)

With this change, it returns a levelCommittedLogger{l, Debug}. Whose Log method becomes:

lvl, ctx := l.committedLevel, l.levels.ctx.With(keyvals...)
//...
if l.levels.promoteErrors {...}  // By default, l.levels.promoteErrors is false, so short circuit this block
//...
if lvl < l.levels.filterLogLevel {...} // By default l.levels.filerLogLevel is 0 and lvl ranges from 0 to 4,
                                       // so short circuit this block
//...
var levelValue string
switch lvl {
case Debug:
    levelValue = l.levels.debugValue
    // Short circuit the rest of the cases, because case Debug is true
}
//...
return ctx.WithPrefix(l.levels.levelKey, levelValue).Log()

In other words, with appropriate substitutions, that last line becomes:

return l.levels.ctx.With(keyvals...).WithPrefix(l.levels.levelKey, l.levels.debugValue).Log()

The only difference between this line and

l.ctx.WithPrefix(l.levelKey, l.debugValue).Log(keyvals...)

...is that you can't overwrite l.levelKey with a different ad-hoc value, which you shouldn't be doing anyway if you're using the levels package.

[jmcgill0brightcove]

I could be misunderstanding this, but it looks like each call for a logger (e.g. "l.Debug()") creates a struct, (levelCommittedLogger) where currently it extends a context. I want to confirm that the memory behavior is similar.

[bishoprook]

For a first pass, log.Context.With() also creates a new struct, so the Debug() call should have the same or fewer allocations. The Log() call in levelCommittedLogger might have a few more allocations since it does a log.Context.With() and a log.Context.WithPrefix(), but they will immediately go out of scope and become eligible for GC.

I don't envision it being a huge difference, but I will add some memory benchmarks to the test suite to check!

[ChrisHines]

Thanks for the well documented PR!

I don't have time for a full review, but I believe returning the levelCommitted logger from the Levels methods will interact badly with log.DefaultCaller. Can you add test code to check that. See #131 for information about when we changed levels.Levels to work correctly with log.DefaultCaller. We should try not to cause a regression in this area.

I will review in more detail when I get the time.

[bishoprook]

@ChrisHines I will check that out and write some tests.

[bishoprook]

@ChrisHines Your intuition is correct, it messes up log.DefaultCaller in the same way. In fact, it causes any Caller to be off-by-one, as compared to using an un-leveled logger. I'm having a hard time coming up with a clean solution.

• Can't just export a decorated context like you did in that PR, because the error promotion functionality has to happen on Log. Until the user calls Log we aren't sure whether there's an error in the logline or not, so we can't make the decision of which level to use, or whether to filter, until the last second. But we don't want levels-aware code to live in package log.
• Because log and levels are different packages, interactions between them have to be exported. So any workaround I write ends up polluting the public API (already happened with HasValue and I don't even like that).

I'm racking my brain trying to come up with a workaround for this that doesn't involve tacking on more junk to the public API of package log or requiring package log to know about levels, and coming up blank.

We can jettison the error promotion, and this becomes super easy: in Debug(), Info(), et al we return either a decorated context as before, or a NopLogger, based on the log level. But I kind of like the error promotion.

I will consider it more this weekend but I'd love it if you had some ideas.

[bishoprook]

Possibly the cleanest solution I can come up with is to add some kind of BeforeLog hook to log.Context. It would have to be part of the exported API. But it would allow getting rid of the HasValue method too.

The hook would be of the signature func(...interface{}) (...interface{}, error) and inside Context.Log we'd do something like:

func (l *Context) Log(keyvals ...interface{}) error {
        kvs := append(l.keyvals, keyvals...)
        if len(kvs)%2 != 0 {
                kvs = append(kvs, ErrMissingValue)
        }
        if l.hasValuer {
                // If no keyvals were appended above then we must copy l.keyvals so
                // that future log events will reevaluate the stored Valuers.
                if len(keyvals) == 0 {
                        kvs = append([]interface{}{}, l.keyvals...)
                }
                bindValues(kvs[:len(l.keyvals)])
        }
        kvs, err := l.beforeLogHook(kvs)
        if err != nil {
            return err
        }
        return l.logger.Log(kvs...)
}

Which would allow consumer packages to add a hook that checks and potentially replaces the keyvals that are about to be logged, and bails out on an error, which could include "don't log this because of the log level."

But it feels clunky and complicated and overkill to support something that isn't a prominent use case.

[ChrisHines]

@bishoprook I agree that BeforeLog is heading in the wrong direction. Given the design choices we've already made with Go-kit logging, I think the most appropriate design is to leverage the Logger interface as much as possible. This means implementing levels.NewLevelFilterLogger and levels.NewEscalateErrLogger that create composable Loggers. It incurs a bit more overhead than your first idea, but the API should be cleaner and it still avoids the cost of formatting the log event into a byte stream, which usually costs the most CPU cycles of logging.

The idea you mentioned in #250 to avoid evaluation of expensive log.Valuers could be handled with a different strategy. Instead of using a Valuer, which is specifically evaluated by Context.Log, you could write a new type, say a LazyValuer that is evaluated by a LazyValueLogger. You then put the LazyValueLogger below the levelFilterLogger in the logger stack. Your logger setup might then look like this:

logger := log.NewLogfmtLogger(w)
logger = LazyValueLogger(logger)
logger = levels.NewLevelFilterLogger(logger, logLevel)
logger = levels.NewEscalateErrLogger(logger)

lvllog := levels.New(logger).With("t", log.DefaultTimestampUTC, "caller", log.DefaultCaller)

In this way LazyValuers you put in the context would only get evaluated if the log event made it past the level filter.

I am not suggesting we add LazyValueLogger to the go-kit packages at this time because I don't know if it is a common enough use case, but any project could implement this strategy on its own.

[peterbourgon]

I think future discussion about the log package, especially levels, will be in the direction established by #357. Accordingly, I'll close this PR. Thanks for the thoughts and effort!