package log, alternate take

[peterbourgon]

Inspired by #16 and the discussion there. @ChrisHines, this isn't very far along, but I'd appreciate your feedback to the general approach, which closely mirrors package metrics...

[tsenart]

Instead of having an EncodeMany function, would it make sense to make the FieldEncoder type variadic?

// FieldEncoder describes a way to encode fields.
type FieldEncoder func(io.Writer, ...Field) error

[aybabtme]

I don't really understand why you would want to encode 1 field at a time, instead of always working with many fields (and 1 field being a special case of many-fields).

@tsenart: +1

[peterbourgon]

@tsenart @aybabtme how does this feel to you both?

[tsenart]

You can use fmt.Fprint here.

[peterbourgon]

@tsenart Thank you.

[tsenart]

Looks good! 👍

[aybabtme]

I like the API, it's exactly all that I want from a logger. Tho, it's important that writes to the Writer be serialized, by a Logger and by the child-Logger that are spawn by invoking With(...).

[aybabtme]

Another thing that we use extensively is:

Log MAY allow tying program actions such as panic to a log level.

Specifically, we use hooks in logrus to report errors to exception reporting services when we log something at a level higher than a specific threshold. This proves immensely useful.

log.AddHook(
    sentry.LogHook("service/blobstash"),  // invoke this hook
    log.Lerror, log.Lfatal, log.Lpanic,   // when we log at this level
)

This is specific to log-level, and the RFC says we should treat log levels as a case of key-value logging. So I guess the hooks here should be fired in function of key-values.

Finally, I'm a bit interested in performance. We use logrus right now but it's spending lots of cycles producing garbage for each line we log. Ideally I'd like to switch to something that's nicer on garbage production. A benchmark would be interesting at some point.

[aybabtme]

When logging errors, package json logs empty objects. logrus has a special case to call .Error() on error-types so that they get logged.

[ChrisHines]

I think this approach has some good ideas, but falls short in places.

Logger interface

The Logger interface is reasonable, but I feel that using Field struct literals repeatedly will get tedious. In my experience, logging is more ad-hoc than metrics or context values. So although having parallel With methods in the logging, metrics, and context packages make sense, I believe that the logging API should streamline the declaration of key/value pairs as much as possible.

Making With variadic helps, and omitting the key names (if one dares) can help too, but we still have a lot of repetition. Let's look at some code adapted from json_logger_test.go

logger.With(
    log.Field{Key: "request.size", Value: 1024},
    log.Field{Key: "response.code", Value: 200},
    log.Field{Key: "response.duration", Value: 42 * time.Millisecond},
    log.Field{Key: "headers", Value: headers},
).Log("OK")

Omitting struct keys:

logger.With(
    log.Field{"request.size", 1024},
    log.Field{"response.code", 200},
    log.Field{"response.duration", 42 * time.Millisecond},
    log.Field{"headers", headers},
).Log("OK")

Using a slice literal

logger.With([]log.Field{
        {"request.size", 1024},
        {"response.code", 200},
        {"response.duration", 42 * time.Millisecond},
        {"headers", headers}}...,
).Log("OK")

The last choice is the best I can do with the proposed API, and it is not horrific, but is still awkward. I know I'm biased by what I've been using, but I feel that the implicitly alternating key value pairs used by log15 are easy to learn and just get out of your way. (In case it matters there is additional precedent for this style set by strings.NewReplacer in the standard library.) Using that idea looks like this:

// Change Logger to:
type Logger interface {
    With(...interface{}) Logger
    Log(string) error
}

logger.With("request.size", 1024, "response.code", 200, "response.duration", 42 * time.Millisecond, "headers", headers).Log("OK")

And we can make one last tweak that may be worthwhile (especially since it can help avoid allocating a new Logger in the common case.

// Change Logger to:
type Logger interface {
    With(...interface{}) Logger
    Log(string, ...interface{}) error
}

logger.Log("OK", "request.size", 1024, "response.code", 200, "response.duration", 42 * time.Millisecond, "headers", headers)

Levels

The approach to log levels is pretty nice. I like that it supports customizing the key and the value in a clean way. I expect that some people will want more than the three levels provided. That would seem easier here than with a lot of logging packages (because the leveled loggers are just a logger with a predefined field), but the Levels struct and supporting functions are less flexible.

It is also not possible to ask for the current levelKey if one wanted to include a custom level in a call to Logger.With. If the intent is to hold the opinion that the three provided levels are sufficient, I am not opposed to it, but I thought I'd bring it up anyway.

Next Steps

I would like to see how this proposal would support logging time-stamps and source location. I would also like to see how composing various logging behaviors would work with this API.

[bg451]

Looks good!

I do like Chris's proposal of tweaking Logger#Log to accept variadic arguments a lot.

[peterbourgon]

Thanks a ton for the feedback! I've been thinking on it quite a bit over the weekend. I want to make sure our package log doesn't repeat the mistakes of the stdlib (namely, that our Logger should be a small interface type) and that it serves equally well for typical weakly-typed application logging and more strongly-typed log-structured data streams à la Kafka. After some reflection I think you're right — I think if the base interface implements variadic interface{} parameters, that gives us the flexibility we need, and allows users to implement more strongly typed layers on top.

I'll run with that idea and hopefully have some commits by EOD.

[peterbourgon]

re: Levels...

I expect that some people will want more than the three levels provided.

Absolutely, and the idea would be that they create their own Levels struct in their application code. The existing Levels type is mostly there to serve as an example.

It is also not possible to ask for the current levelKey if one wanted to include a custom level in a call to Logger.With

1. The level key is declared; there's no need to introspect on it, because the user has explicitly set it.
2. Custom, one-off levels are tricky, and I'm not sure ever a good idea. Do you have a use case?

[sztanpet]

May I raise my objections about this? This seems magic and very "un-go like".
I would rather initialize the logger with functional options, as described here
http://dave.cheney.net/2014/10/17/functional-options-for-friendly-apis
and actually have typed option functions for passing things that are easily
extensible later and can leverage the type system properly

[peterbourgon]

@sztanpet One is free to construct typed wrappers around the core. If you'd like to provide me a use case, I'm happy to commit an example to show you what I mean.

[sztanpet]

So this is not supposed to be used by end users directly? My use case is purely not hiding the fact that arguments for With(...interface{}) come in key-value pairs (sure, a run-time panic is the minimum that should happen if the assumption is violated but in an ideal world this should be a compile-time error) and having concrete types as much as possible, maybe not for the value argument

[peterbourgon]

@sztanpet Yes, it can and should be used by end-users who need the convenience of arbitrary types at the callsite. And it's not unprecedented to have pairwise variadic arguments. If you want to enforce further (compile-time) type checking, it's straightforward to write a wrapper that reifies your specific use-case(s).

type myLogger struct {
    log.Logger
}

func NewMyLogger(logger log.Logger) myLogger {
    return myLogger{logger}
}

func (l myLogger) LogRequest(context string, requestDuration time.Duration) {
    l.Logger.Log("Request", "context", context, "request_duration", requestDuration.String())
}

[sztanpet]

Okay, thanks for considering my points

[aybabtme]

my last comment was lost with the change to varargs: if v is of type error, it will be encoded as an empty {} by the JSON encoder. Ideally it should be special cased to call .Error() if v is of type error.

[tsenart]

Logging ought to be as structured as possible but its structure is entirely dependent on the requirements and conventions of an organisation. I see no reason to give special meaning to a field called msg, or any other field whatsoever.

The users of this package could well encode their own conventions and requirements through extension.
One thing that occurred to me while writing the below code example is that the With method becomes somewhat redundant since you can encode the constant keys in this enclosing layer.

// Logger wraps a gokit Logger with organisational specifics.
type Logger struct { log.Logger }

// Log wraps the inner Log method with constant key values.
func (l Logger) Log(keyvals ...interface{}) error {
    return l.Logger.Log(append(keyvals, "time", time.Now().UTC())...)
}

// Msg logs a message s mapped to a "msg" key, along with the other keyvals.
func (l Logger) Msg(s string, keyvals ...interface{}) error {
    return l.Log(append(keyvals, "msg", s)...)
}

[aybabtme]

I guess I'm convinced, however the With remains important in my opinion. We want to be able to do:

l := log.With(
    "filename", filename,
    "filesize", filesize,
)

l.Info("beginning transfer")

if err := xfer(); err != nil {
    l.Error("failed to transfer", "err", err)
} else {
    l.Info("transfer complete")
}

Without needing a new type for each such uses of that, since it's a very common use.

[ChrisHines]

One thing that occurred to me ... is that the With method becomes somewhat redundant since you can encode the constant keys in this enclosing layer.

That is an interesting point. With could be implemented as a general purpose function like this:

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

func With(l Logger, keyvals ...interface{}) Logger {
    return LoggerFunc(func(kvs ...interface{}) error {
        return l.Log(append(keyvals, kvs...)...)
    })
}

type LoggerFunc func(...interface{}) error

func (f LoggerFunc) Log(keyvals ...interface{}) error {
    return f(keyvals...)
}

If we want to allow Loggers to optimize With in some way then the generic With function could check for an optional interface the same way that io.Copy checks for io.WriterTo and io.ReaderFrom like so:

func With(l Logger, keyvals ...interface{}) Logger {
    if l, ok := l.(Wither); ok {
        return l.With(keyvals...)
    }
    return LoggerFunc(func(kvs ...interface{}) error {
        return l.Log(append(keyvals, kvs...)...)
    })
}

type Wither interface {
    With(keyvals ...interface{}) Logger
}

I have been writing implementations of Logger to see what can be accomplished and I am finding that many of my loggers exist primarily to wrap the Log method for various purposes. I ended up writing a helper type to reuse the With method of a base logger, but the above code is cleaner and a single method interface has a definite appeal as a lowest common denominator.

[tsenart]

I like where this is heading! Peter: What do you think?

On Wednesday, April 1, 2015, Chris Hines [email protected] wrote:

One thing that occurred to me ... is that the With method becomes
somewhat redundant since you can encode the constant keys in this enclosing
layer.

That is an interesting point. With could be implemented as a general
purpose function like this:

type Logger interface {
Log(keyvals ...interface{}) error
}
func With(l Logger, keyvals ...interface{}) Logger {
return LoggerFunc(func(kvs ...interface{}) error {
return l.Log(append(keyvals, kvs...)...)
})
}
type LoggerFunc func(...interface{}) error
func (f LoggerFunc) Log(keyvals ...interface{}) error {
return f(keyvals...)
}

If we want to allow Loggers to optimize With in some way then the generic
With function could check for an optional interface the same way that
io.Copy checks for io.WriterTo and io.ReaderFrom like so:

func With(l Logger, keyvals ...interface{}) Logger {
if l, ok := l.(Wither); ok {
return l.With(keyvals...)
}
return LoggerFunc(func(kvs ...interface{}) error {
return l.Log(append(keyvals, kvs...)...)
})
}
type Wither interface {
With(keyvals ...interface{}) Logger
}

I have been writing implementations of Logger to see what can be
accomplished and I am finding that many of my loggers exist primarily to
wrap the Log method for various purposes. I ended up writing a helper
type to reuse the With method of a base logger, but the above code is
cleaner and a single method interface has a definite appeal as a lowest
common denominator.

—
Reply to this email directly or view it on GitHub
#21 (comment).

Sent from Gmail Mobile

[tsenart]

Although I think the With interface is redundant at this point since it's
identical to the Log interface, I'm positive about making With a function that
wraps another Logger with constant keys.

On Wednesday, April 1, 2015, Tomás Senart [email protected] wrote:

I like where this is heading! Peter: What do you think?

On Wednesday, April 1, 2015, Chris Hines <[email protected]
javascript:_e(%7B%7D,'cvml','[email protected]');> wrote:

One thing that occurred to me ... is that the With method becomes
somewhat redundant since you can encode the constant keys in this enclosing
layer.

That is an interesting point. With could be implemented as a general
purpose function like this:

type Logger interface {
Log(keyvals ...interface{}) error
}
func With(l Logger, keyvals ...interface{}) Logger {
return LoggerFunc(func(kvs ...interface{}) error {
return l.Log(append(keyvals, kvs...)...)
})
}
type LoggerFunc func(...interface{}) error
func (f LoggerFunc) Log(keyvals ...interface{}) error {
return f(keyvals...)
}

If we want to allow Loggers to optimize With in some way then the
generic With function could check for an optional interface the same way
that io.Copy checks for io.WriterTo and io.ReaderFrom like so:

func With(l Logger, keyvals ...interface{}) Logger {
if l, ok := l.(Wither); ok {
return l.With(keyvals...)
}
return LoggerFunc(func(kvs ...interface{}) error {
return l.Log(append(keyvals, kvs...)...)
})
}
type Wither interface {
With(keyvals ...interface{}) Logger
}

I have been writing implementations of Logger to see what can be
accomplished and I am finding that many of my loggers exist primarily to
wrap the Log method for various purposes. I ended up writing a helper
type to reuse the With method of a base logger, but the above code is
cleaner and a single method interface has a definite appeal as a lowest
common denominator.

—
Reply to this email directly or view it on GitHub
#21 (comment).

Sent from Gmail Mobile

Sent from Gmail Mobile

[BRMatt]

Sorry if this is a basic question, but I'm having a bit of trouble understanding how log levels will work if you want to append key/value pairs after the levels have been setup. For example, I may want certain fields to be included on all log lines (request_id), and some only within a specific section (e.g. the name of a library that's being passed a logger).

If I were doing it without levels I could do:

l := NewPreficLogger(&bytes.Buffer{})
request_logger := l.With("request_id", "....")
lib_logger := request_logger.With("lib", "stripe")

However when I introduce levels:

l := NewPreficLogger(&bytes.Buffer{})
request_logger := NewLevels(l.With("request_id", "...."), LevelKey("l"), DebugLevelValue("debug"), InfoLevelValue("info"), ErrorLevelValue("err"))

// Can no longer call this as `request_logger` is no longer a Logger instance
lib_logger.With("lib", "stripe")

The only way I see around this is to keep a copy of the logger before you set its levels, then apply the levels each time you call With(), which doesn't seem very easy to use. EDIT: Or you apply With() to each of the level loggers, which also doesn't seem sustainable.

[tsenart]

Looks like me.

[peterbourgon]

@BRMatt

For example, I may want certain fields to be included on all log lines (request_id), and some only within a specific section (e.g. the name of a library that's being passed a logger).

base := log.NewPrefixLogger(&bytes.Buffer{})
levels := log.NewLevels(base.With("common_key", "value"), log.LevelKey("l"))
levels.Debug = levels.Debug.With("debug_only_key", "value")
levels.Info = levels.Info.With("info_only_key", "value")

if something {
    levels.Debug.Log("something!")
}
levels.Info.Log("info", "specific_context", someVal)

[BRMatt]

@peterbourgon Thanks, but I'm not sure that's quite what I was after. I'm trying to find a nice way to call With() on some levels that follows the same semantics as Logger's With() (e.g. doesn't mutate the levels object). Hopefully this example is clearer:

base := log.NewPrefixLogger(&bytes.Buffer{})
levels := log.NewLevels(base.With("common_key", "value"), log.LevelKey("l"))
// common_key=value l=info msg=something
levels.Info.Log("something")

var a stripe.Client = NewStripeApi(..., levels.With("lib", "stripe"))
a.SomeMethod()

func (s *stripe.Client) SomeMethod() {
 // common_key=something l=info lib=stripe msg="some info here"
 s.l.Info.Log("some info here")

 // common_key=something l=error lib=stripe msg="something went wrong"
 s.l.Error.Log("something went wrong")

 // common_key=something l=debug lib=stripe msg="logs useful for debugging"
 s.l.Debug.Log("logs useful for debugging")
}

[peterbourgon]

@BRMatt You can easily get levels.With by defining your own Levels object :)

[peterbourgon]

@aybabtme @ChrisHines @tsenart I like the single-method Logger interface, I'll definitely write that up. I'm going to have to prototype the LoggerFunc/Wither stuff to see how it feels, I'm guessing it will be OK but it feels a little heavy on the page right now.

This is all pretty far removed from the simplest logging use cases. Can we collectively decide on some nice wrappers for a couple of common cases? Perhaps something that apes the stdlib package log logger?

[ChrisHines]

@peterbourgon I did some prototyping on this and the biggest sticking point remains where in the chain values are bound. As I said in the discussion on PR #16, it is tricky to know the right number of stack frames to skip when calling runtime.Callers (or equivalent) when you want to include source file and line number.

Looking at the stdlib package log for use cases I see the following features:

func SetFlags(flag int)  // enables any combination of date, time, or source location
func SetOutput(w io.Writer)
func SetPrefix(prefix string) // we could interpret this as a limited form of With()

Also stdlib log uses package fmt for formatting, and we are doing structured logging, so controlling the way keyvals are formatted into a io.Writer is obviously important.

[peterbourgon]

I'd like to defer solving the runtime.Callers issue and merge this PR in the short term. Is there anything missing for anyone's immediate use cases?

[aybabtme]

🚢

[ChrisHines]

LGTM

[tsenart]

[peterbourgon]

Failures in CI due to a Prometheus issue, fix pending...