kit/log/levels: support filtering

[AlmogBaku]

Intro

I believe for some scenarios it's a good practice to "throw" a lot of logs(i.e. debugging/info), and in case of need to "expose them" in order to track of bugs.

However, you doesn't necessary want to send all those bugs to the "external" logs management(i.e. debug a single connection details, especially for real-time use cases). Mechanism of filtering by log-levels can be very useful for this scenarios.

Suggestion

Adding "just a layer of filtering" to the current structure is feasible, however- it will be based on string comparisons instead of mathematical comparisons (from DEBUG logs and above)

In order to achieve a verbosity level, I suggest to use a new type type LogLevel int, and to compare base on it.
Example: https://gist.github.com/AlmogBaku/61f183350e10173377f85ee940a84741

If it make sense, i'd love to work on a PR to the existing kit/log/levels API, that contains this enhancement.

[peterbourgon]

Dynamic inspection of log level with every Log invocation imposes a significant performance cost that we (ideally) want to avoid, or (at worst) make it explicitly opt-in. Let me propose this alternative to the existing log/levels package, which includes a concept of numeric level.

type Level int

var (
    LevelNone Level = iota
    LevelError
    LevelInfo
    LevelDebug
)

type Levels struct {
    Error log.Logger
    Info  log.Logger
    Debug log.Logger
}

func NewLevels(logger log.Logger, level Level) Levels {
    levels := Levels{
        Error: log.NewNopLogger(),
        Info:  log.NewNopLogger(),
        Debug: log.NewNopLogger(),
    )
    if level >= LevelError {
        levels.Error = log.NewContext(logger).With("level", "error")
    }
    if level >= LevelInfo {
        levels.Info = log.NewContext(logger).With("level", "info")
    }
    if level >= LevelDebug {
        levels.Debug = log.NewContext(logger).With("level", "debug")
    }
    return levels
}

func Example() {
    logger := log.NewLogfmtLogger(os.Stdout)
    levels := levels.New(logger, LevelInfo)

    levels.Debug.Log("msg", "this will NOT get printed")
    levels.Info.Log("msg", "this will get printed")
    levels.Error.Log("msg", "this will also get printed")
}

Alternative

It is also possible to opt-in to paying a runtime cost to get a slightly easier API.

func NewKeyBasedLeveledLogger(logger log.Logger, level Level) log.Logger {
    return leveledLogger{logger, level}
}

type leveledLogger struct {
    logger log.Logger
    level  Level
}

func (l leveledLogger) Log(keyvals ...interface{}) {
    for i := 0; i<len(keyvals); i += 2 {
        // Pseudocode
        k, v := keyvals[i], keyvals[i+1]
        if k != "level" {
            continue
        }
        if parseLevel(v) > l.level {
            return // don't log this one
        }
        break
    }
    l.logger.Log(keyvals...)
}

func Example() {
    var logger log.Logger
    logger = log.NewLogfmtLogger(os.Stdout)
    logger = NewKeyBasedLevelLogger(logger, LevelInfo)

    logger.Log("level", "debug", "msg", "this is NOT printed")
    logger.Log("level", "info", "msg", "this is printed")
    logger.Log("level", "error", "msg", "this is also printed")
    logger.Log("msg", "without a level, this gets printed, but we can change that behavior")
}

[peterbourgon]

@csguy Also keen on your input here. I've seen a lot of interest in numeric levels lately...

[AlmogBaku]

Following up to the discussion on Slack, @peterbourgon and I raised an option to return a Levels interface that extends the current Logger:

type levels.Logger interface {
    log.Logger
    Debug(keyvals ...interface{})
    Info(keyvals ...interface{})
    Error(keyvals ...interface{})
}

So instead of writing a long command to print log, you can use a shorthand:

logger.Log("level", levels.Debug, "msg", "this is NOT printed")

or

logger.NewContext(logger).With("level", levels.Debug)

[AlmogBaku]

Another idea is to cast the first option @peterbourgon raised(multiple loggers on init) implement the interface above.

Then the default Log(keyvals ...interface{}) will return the default Logger.
A good question is what is the "default logger"? (ie. python’s default is WARNING; log4j- DEBUG; supervisord- INFO...)

This idea will allow us to:

1. Make the levels be casted to a common interface
2. Easier integration for existence implementation of the Logger interface

---

@peterbourgon raised an idea to add an option strict bool to the constructor, then if the strict is false to allow logging logs without level(default logger)

[ChrisHines]

There are a lot of ideas mentioned above. Here are my general comments:

I think @peterbourgon is overestimating the relative cost of iterating over the keyvals slice looking for specific keys and values. Excluding actual I/O operations, the two most expensive steps (in decreasing order of cost) of outputting a log event from kit/log are:

1. Formatting the []keyvals into a byte stream.
2. Allocating the elements of the []keyvals when the initial call to a Log method.

Adding a filtering layer as in @AlmogBaku's initial proposal and @peterbourgon's alternative proposal does not cost much more than directly calling nopLogger.Log. My benchmark tests point to the cost being about +5% in both the positive and negative case for logfmt output. The same benchmark showed a +400% cost of formatting the logfmt output relative to dropping the event before the formatting step with either strategy. The benchmarks did not measure the cost of I/O, instead writing the logfmt output to ioutil.Discard.

As far as I know it is impossible to eliminate the second cost without wrapping every call to Log with an if statement in the application code. The benefit of filtering debug log events comes entirely from avoiding the formatting and I/O operations. But clearly these savings can be huge and the cost of inspecting the keyvals in a filtering layer seems small by comparison.

The benefit of using a filtering layer lies in how nicely it fits with the philosophy of kit/log and Go kit in general. Go kit encourages the philosophy of using composable layers of behavior that each implement the same narrow interface--the decorator pattern. This philosophy also allows each application to opt in to the layers of behavior it is willing to pay the cost for.

For further reading about why the log/levels package has taken its current form, please see these discussions: #63, #76, #131, and #157. The discussion in #252 is also worth reviewing. These discussions should clarify the challenges we must overcome with leveled logging for kit/log. Specifically, a good implementation should be composable with log.Context, not break the behavior of a log.Caller in any wrapped Context, and friendly to packages that accept only log.Logger values and are unaware of levels. The current implementation of log/levels meets all of these challenges pretty well.

In my opinion, we should focus on a good API for a new decorator that filters log events containing specific levels. I think this means iterating on @peterbourgon's alternate approach and possibly changing the level values from strings to ints that format as strings if the log event reaches the output layer.

[peterbourgon]

Thanks very much, Chris. I will update the log/README.md with more context, and (especially) those requirements for new loggers, which seem to slip my mind whenever we have these discussions.

[AlmogBaku]

@ChrisHines I'm not sure I understood why do you think(or do you?) that the Levels can't be cast to the common Logger interface as suggested above? #269 (comment)

IMO, We can have a common Logger with a Context that upgrades the Logger interface

[ChrisHines]

@AlmogBaku I am not sure I have completely understood your idea for a Levels interface, maybe more details would help. Based on what you posted above it seems similar to what we had in the early days of the levels package and moved away from because it didn't compose well with other features. Issues #63 and #131 discuss some of those problems. You will note that before PR #157 was merged type levels.Levels implemented an interface very similar to your suggestion. The idea of adding a Log method to Levels was also suggested in the discussion leading to that PR (as seen here #131 (comment)).

So, it feels to me like we've been down this path before, but as I said maybe I am missing an important difference in your idea. If you believe it can work then I encourage you to give it a try. Fork the project, experiment with the idea, see how it feels, submit a PR back to us and I will gladly review it. If your idea works then Go kit gets better; and even if it doesn't, we will have learned something more about the problem.

[AlmogBaku]

Ok, so just to recap my understandings:

1. Level Loggers should return Logger and not offer a "keyval function"
2. We can't cast the levels to the Logger interface (is there any workaround for that?)
3. We can, and probably need to change the levels to iota rather than strings
4. The question of how to filter(iterating vs "on-init"[nooplogger]) still stands

[ChrisHines]

@AlmogBaku That seems like a reasonable summary, although it seems to me that (1) makes (2) unnecessary, so I don't understand what workaround is required.