New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Standard logger interface. #1

Closed
leehambley opened this Issue Nov 6, 2017 · 47 comments

Comments

Projects
None yet
@leehambley

leehambley commented Nov 6, 2017

I'm sitting in the upper balcony and wondered if here was the place to get the new standard logger interface nailed down.

Keeping interfaces small is something I can stand behind, but logging seems like a nebulous topic.

I'm going to flesh this out later, first thought is that logging should concern itself with the Printf family of functions, and levels should be implemented by returning a new logger with an internal tags representing the level.

@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon Nov 6, 2017

There has been extensive discussion about a standard logger interface earlier this year. We couldn't agree on the problems we wanted to solve with such an interface, nor (naturally) the shape of the thing in the end.

This talk from Chris provides some context to his/our conclusion from the whole endeavor:

Note that we do not plan to submit our proposal to the Go project because we now believe that a standard logging interface is the wrong approach for the wider Go community. Instead we believe that widely shared libraries should expose event data via a more richly typed callback API. This approach allows applications to optionally handle the events as they need. Perhaps they log (with their preferred logging implementation), or perhaps they do something else. See, for example, how the golang.org/pkg/net/http/httptrace package enables many more use cases than just logging. I briefly touched on this topic starting at slide 47 of my presentation.

peterbourgon commented Nov 6, 2017

There has been extensive discussion about a standard logger interface earlier this year. We couldn't agree on the problems we wanted to solve with such an interface, nor (naturally) the shape of the thing in the end.

This talk from Chris provides some context to his/our conclusion from the whole endeavor:

Note that we do not plan to submit our proposal to the Go project because we now believe that a standard logging interface is the wrong approach for the wider Go community. Instead we believe that widely shared libraries should expose event data via a more richly typed callback API. This approach allows applications to optionally handle the events as they need. Perhaps they log (with their preferred logging implementation), or perhaps they do something else. See, for example, how the golang.org/pkg/net/http/httptrace package enables many more use cases than just logging. I briefly touched on this topic starting at slide 47 of my presentation.

@leehambley

This comment has been minimized.

Show comment
Hide comment
@leehambley

leehambley Nov 6, 2017

leehambley commented Nov 6, 2017

@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon Nov 6, 2017

I didn't see Brian's talk, but I can say, based on extensive experience, that a standard logger interface is approximately the Kobayashi Maru of Go proposals. I can't imagine a more difficult idea to start with.

peterbourgon commented Nov 6, 2017

I didn't see Brian's talk, but I can say, based on extensive experience, that a standard logger interface is approximately the Kobayashi Maru of Go proposals. I can't imagine a more difficult idea to start with.

@leehambley

This comment has been minimized.

Show comment
Hide comment
@leehambley

leehambley Nov 6, 2017

tl;dr @peterbourgon his talk was about "go for the enterprise" which includes, but is not limited to code gen, better "non standard" libraries (stdlib++ :trollface: ). I'm grossly under representing the scope of his talk.

I read into the initial linked proposal from golang-dev and one thing that struck me is the discussion about performance with no comparison to the log package. Partly it seems because they're principally interested in the KV map printing (there's on example however that just enumerates args to a printf-like)

I wonder if they're all failing to see wood for trees. If it's faster than log (or at least more predictable.) I have in mind issues with Node.JS in ~2016/17 when it was discovered they could /half/ execution time by moving rendering of the progress bar out of the main thread, even if the stdout device was buffered by the terminal emulator and/or shell.

It's too late, and I've got to be up stupid early for a flight - but I wonder if we couldn't be more pragmatic.

First impression after reading this is that Ross Light et al's proposal seems like it would cause a log of garbage, but I didn't read deeply enough to "get it", seems like all the decisions they made make sense given their self-imposed constraints.

Since go-commons/commons is only focused on defining an interface, and not necessarily an implementation, maybe it gives less for people to argue about?

Note: the link in your comment with three bullet points, you link the proposal from Ross Light &c.'s twice.

leehambley commented Nov 6, 2017

tl;dr @peterbourgon his talk was about "go for the enterprise" which includes, but is not limited to code gen, better "non standard" libraries (stdlib++ :trollface: ). I'm grossly under representing the scope of his talk.

I read into the initial linked proposal from golang-dev and one thing that struck me is the discussion about performance with no comparison to the log package. Partly it seems because they're principally interested in the KV map printing (there's on example however that just enumerates args to a printf-like)

I wonder if they're all failing to see wood for trees. If it's faster than log (or at least more predictable.) I have in mind issues with Node.JS in ~2016/17 when it was discovered they could /half/ execution time by moving rendering of the progress bar out of the main thread, even if the stdout device was buffered by the terminal emulator and/or shell.

It's too late, and I've got to be up stupid early for a flight - but I wonder if we couldn't be more pragmatic.

First impression after reading this is that Ross Light et al's proposal seems like it would cause a log of garbage, but I didn't read deeply enough to "get it", seems like all the decisions they made make sense given their self-imposed constraints.

Since go-commons/commons is only focused on defining an interface, and not necessarily an implementation, maybe it gives less for people to argue about?

Note: the link in your comment with three bullet points, you link the proposal from Ross Light &c.'s twice.

@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon commented Nov 6, 2017

Oh, sorry; here's the proposal from Chris and myself; I've updated the link.

@leehambley

This comment has been minimized.

Show comment
Hide comment
@leehambley

leehambley Nov 6, 2017

Thanks for updating the link. I've just dug up the benchmarks they used in the golang-dev list and extended them slightly to test the stdlib log package and the results are astounding:

First, the various loggers they tested with ioutil.Discard as the sink:

[~/bench-logging]$ go test -bench .
goos: darwin
goarch: amd64
BenchmarkGokitLogfmt-8           2000000               838 ns/op
BenchmarkLog15Logfmt-8            500000              2852 ns/op
BenchmarkLogrusLogfmt-8           500000              3180 ns/op
BenchmarkStdlibLogPrintln-8      5000000               310 ns/op
PASS
ok      _/Users/leehambley/bench-logging        7.522s

I added BenchmarkStdlibLogPrintln, and at 310ns/op it's significantly faster than the next best, which is again ~3.5x slower than the next best. Takeaway: this is a meaningless synthetic benchmark for most Gophers, most of the time.

I can for sure afford 0.000002852 seconds to write a log line (2852 ns) in nearly every application I've ever written, and /doing/ anything with this will take an order of magnitude more. In a real world with something consuming my output (even with a buffer) or sending it on a network, or pushing it into a ring buffer, it will be slower for sure.

With speed of the sink in mind, I decided to replace the ioutil.Discard with os.Stderr, and redirect go test -bench's output to a file. I allowed the process to ruin my terminal with a few hundred thousand log lines, and examined the contents of the file:

goos: darwin
goarch: amd64
BenchmarkGokitLogfmt-8        	  500000	      4823 ns/op
BenchmarkLog15Logfmt-8        	  200000	      7685 ns/op
BenchmarkLogrusLogfmt-8       	  100000	     19250 ns/op
BenchmarkStdlibLogPrintln-8   	  500000	      3335 ns/op
PASS
ok  	_/Users/leehambley/bench-logging	8.701s

So connecting the logger to anything "real" (including tmux under iterm2 running zsh, which I take for a pretty typical developer use-case, however for sure there's the systemd, syslog redirect, docker log capture, etc use-cases which are more likely to affect real-world perf.

My general take-away is that this benchmark wasn't very good to begin with, as I can't explain Logrus, unless it's doing some inference on the output device and avoiding doing the work entirely. (fwiw, redirecting to a file yields similar results)

I think I'd much rather keep the conversation on a high level about the interface, it might be sane to take a simple step in the right direction:

  • Take the current log.Logger and define it's interface as the interface?
  • augment with optional "upgrades" avaialble via type assertion to support more complex cases?

leehambley commented Nov 6, 2017

Thanks for updating the link. I've just dug up the benchmarks they used in the golang-dev list and extended them slightly to test the stdlib log package and the results are astounding:

First, the various loggers they tested with ioutil.Discard as the sink:

[~/bench-logging]$ go test -bench .
goos: darwin
goarch: amd64
BenchmarkGokitLogfmt-8           2000000               838 ns/op
BenchmarkLog15Logfmt-8            500000              2852 ns/op
BenchmarkLogrusLogfmt-8           500000              3180 ns/op
BenchmarkStdlibLogPrintln-8      5000000               310 ns/op
PASS
ok      _/Users/leehambley/bench-logging        7.522s

I added BenchmarkStdlibLogPrintln, and at 310ns/op it's significantly faster than the next best, which is again ~3.5x slower than the next best. Takeaway: this is a meaningless synthetic benchmark for most Gophers, most of the time.

I can for sure afford 0.000002852 seconds to write a log line (2852 ns) in nearly every application I've ever written, and /doing/ anything with this will take an order of magnitude more. In a real world with something consuming my output (even with a buffer) or sending it on a network, or pushing it into a ring buffer, it will be slower for sure.

With speed of the sink in mind, I decided to replace the ioutil.Discard with os.Stderr, and redirect go test -bench's output to a file. I allowed the process to ruin my terminal with a few hundred thousand log lines, and examined the contents of the file:

goos: darwin
goarch: amd64
BenchmarkGokitLogfmt-8        	  500000	      4823 ns/op
BenchmarkLog15Logfmt-8        	  200000	      7685 ns/op
BenchmarkLogrusLogfmt-8       	  100000	     19250 ns/op
BenchmarkStdlibLogPrintln-8   	  500000	      3335 ns/op
PASS
ok  	_/Users/leehambley/bench-logging	8.701s

So connecting the logger to anything "real" (including tmux under iterm2 running zsh, which I take for a pretty typical developer use-case, however for sure there's the systemd, syslog redirect, docker log capture, etc use-cases which are more likely to affect real-world perf.

My general take-away is that this benchmark wasn't very good to begin with, as I can't explain Logrus, unless it's doing some inference on the output device and avoiding doing the work entirely. (fwiw, redirecting to a file yields similar results)

I think I'd much rather keep the conversation on a high level about the interface, it might be sane to take a simple step in the right direction:

  • Take the current log.Logger and define it's interface as the interface?
  • augment with optional "upgrades" avaialble via type assertion to support more complex cases?
@daved

This comment has been minimized.

Show comment
Hide comment
@daved

daved Nov 6, 2017

@peterbourgon

Kobayashi Maru? Are you trying to suggest that we fork Go to make establishing a standard logger interface possible?

You'd be kicked out of Starfleet. There's no way it would work a second time.

daved commented Nov 6, 2017

@peterbourgon

Kobayashi Maru? Are you trying to suggest that we fork Go to make establishing a standard logger interface possible?

You'd be kicked out of Starfleet. There's no way it would work a second time.

@enrichman

This comment has been minimized.

Show comment
Hide comment
@enrichman

enrichman Nov 6, 2017

If I understood the idea behind this repo and Brian's talk was about creating a Go version of the Apache Commons, so basically a Swiss Army knife built slightly on top of the standard library.

I agree that probably the Logger is a bit out of scope, and maybe we should focus on discussing about more common everyday problems (ordering things, reading/writing files, map functions and stuff like that).

enrichman commented Nov 6, 2017

If I understood the idea behind this repo and Brian's talk was about creating a Go version of the Apache Commons, so basically a Swiss Army knife built slightly on top of the standard library.

I agree that probably the Logger is a bit out of scope, and maybe we should focus on discussing about more common everyday problems (ordering things, reading/writing files, map functions and stuff like that).

@leehambley

This comment has been minimized.

Show comment
Hide comment
@leehambley

leehambley Nov 6, 2017

I agree that probably the Logger is a bit out of scope, and maybe we should focus on discussing about more common everyday problems (ordering things, reading/writing files, map functions and stuff like that).

All our commons stuff will need a logger though, so it's a pertinent part of the discussion I would affirm. I just wanted to highlight that discussions about performance to date are moot in the face of comparing the internals of juggling a few hundred bytes of data and maybe discarding it anyway, vs. real-world logger usage, in which case the stdlib is by far the most performant, and simplest.

leehambley commented Nov 6, 2017

I agree that probably the Logger is a bit out of scope, and maybe we should focus on discussing about more common everyday problems (ordering things, reading/writing files, map functions and stuff like that).

All our commons stuff will need a logger though, so it's a pertinent part of the discussion I would affirm. I just wanted to highlight that discussions about performance to date are moot in the face of comparing the internals of juggling a few hundred bytes of data and maybe discarding it anyway, vs. real-world logger usage, in which case the stdlib is by far the most performant, and simplest.

@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon Nov 6, 2017

A performance comparison between either of the linked logger proposals and the stdlib logger is apples-and-oranges. They have completely different APIs.

peterbourgon commented Nov 6, 2017

A performance comparison between either of the linked logger proposals and the stdlib logger is apples-and-oranges. They have completely different APIs.

@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon Nov 7, 2017

Also:

All our commons stuff will need a logger though, so it's a pertinent part of the discussion I would affirm.

The current best practice seems to be that each package should

  • define its own domain-specific interface for structured events;
  • provide a no-op implementation;
  • optionally, provide a default implementation, adapting a suitably low-level primitive like io.Writer;
  • accept that interface as a param in relevant type constructors (NOT a package global); and,
  • "log" using that interface where necessary.

(n.b. Chris and my proposal, above, was intended to be a general interface that would satisfy those criteria for all packages that didn't care about reifying anything more domain-specific.)

peterbourgon commented Nov 7, 2017

Also:

All our commons stuff will need a logger though, so it's a pertinent part of the discussion I would affirm.

The current best practice seems to be that each package should

  • define its own domain-specific interface for structured events;
  • provide a no-op implementation;
  • optionally, provide a default implementation, adapting a suitably low-level primitive like io.Writer;
  • accept that interface as a param in relevant type constructors (NOT a package global); and,
  • "log" using that interface where necessary.

(n.b. Chris and my proposal, above, was intended to be a general interface that would satisfy those criteria for all packages that didn't care about reifying anything more domain-specific.)

@progrium

This comment has been minimized.

Show comment
Hide comment
@progrium

progrium Nov 7, 2017

Also, we're not creating another logger, this is an attempt to standardize a logging interface. Any performance testing should only be of the interface and the data structures used in that interface.

For our purposes perhaps we should suggest stawman proposals? At the very least to determine the scope of what we're trying to define? For example, we could go deep on an API to work with and configure loggers and logging, but something as simple as this (but not this) would go a LONG way:

type Logger interface {
	With(args ...interface{}) Logger

	DebugLogger
	InfoLogger
	WarnLogger
	ErrorLogger
}

type DebugLogger interface {
	Debug(args ...interface{})
	Debugf(template string, args ...interface{})
	Debugw(msg string, keysAndValues ...interface{})
}

type InfoLogger interface {
	Info(args ...interface{})
	Infof(template string, args ...interface{})
	Infow(msg string, keysAndValues ...interface{})
}

type WarnLogger interface {
	Warn(args ...interface{})
	Warnf(template string, args ...interface{})
	Warnw(msg string, keysAndValues ...interface{})
}

type ErrorLogger interface {
	Error(args ...interface{})
	Errorf(template string, args ...interface{})
	Errorw(msg string, keysAndValues ...interface{})
}

progrium commented Nov 7, 2017

Also, we're not creating another logger, this is an attempt to standardize a logging interface. Any performance testing should only be of the interface and the data structures used in that interface.

For our purposes perhaps we should suggest stawman proposals? At the very least to determine the scope of what we're trying to define? For example, we could go deep on an API to work with and configure loggers and logging, but something as simple as this (but not this) would go a LONG way:

type Logger interface {
	With(args ...interface{}) Logger

	DebugLogger
	InfoLogger
	WarnLogger
	ErrorLogger
}

type DebugLogger interface {
	Debug(args ...interface{})
	Debugf(template string, args ...interface{})
	Debugw(msg string, keysAndValues ...interface{})
}

type InfoLogger interface {
	Info(args ...interface{})
	Infof(template string, args ...interface{})
	Infow(msg string, keysAndValues ...interface{})
}

type WarnLogger interface {
	Warn(args ...interface{})
	Warnf(template string, args ...interface{})
	Warnw(msg string, keysAndValues ...interface{})
}

type ErrorLogger interface {
	Error(args ...interface{})
	Errorf(template string, args ...interface{})
	Errorw(msg string, keysAndValues ...interface{})
}
@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon Nov 7, 2017

If nothing else, I hope everyone can agree that any blessed Logger interface should be structured, i.e. always key/val, never Printf.

peterbourgon commented Nov 7, 2017

If nothing else, I hope everyone can agree that any blessed Logger interface should be structured, i.e. always key/val, never Printf.

@leehambley

This comment has been minimized.

Show comment
Hide comment
@leehambley

leehambley Nov 7, 2017

Also, we're not creating another logger, this is an attempt to standardize a logging interface. Any performance testing should only be of the interface and the data structures used in that interface.

I assumed that's what @peterbourgon meant when he mentioned the Kobiashi Maru, the solution was to "redefine the problem" - the upstream problem seems to be nobody can agree on an implementation, our redefinition of a problem is just to define an interface. Re-reading I suspect he meant "insoluble problem", so that's probably just my naïvety with the uphill struggle leaking out.

Good that someone finally posted some code. My personal opinion however @progrium that the interface you proposed is too wide (just imagine all the mocks, etc), why not something like:

type Logger interface {
    With(...interface{}) Logger
    Level(Level) Logger
        
    Printf(...interface{})
    # etc...
    Map(map[string]interface{})
}

And then usage like this:

l := commons.NewLogger(os.Stdout).With(map["prefix"]["foo bar"])
# I'd like to see an example of what @progrium would use
# `With()` for, function sig doesn't give many clues

l.Level(commons.Debug).Printf("Hello Developers")
l.Level(commons.Info).Printf("Hello World")
# - Info could be implied
l.Printf("Hello wOrld")

.With can maybe also take functions like Dave Cheney's https://dave.cheney.net/2014/10/17/functional-options-for-friendly-apis

That'd allow us to configure patterns, flags, prefixes, etc, etc, etc and it would only require one general purpose config function and provide scope for expansion for extra special use-cases.

Perhaps we should pull, not push… that is, pick a logging interface that works for us (or more than one) in the commons repo, and expect that slowly, through determined, persistent effort we can work towards having our logger blessed, or is it more realistic to expect the Go team to bless their stdlib concrete logger's API as an interface?

leehambley commented Nov 7, 2017

Also, we're not creating another logger, this is an attempt to standardize a logging interface. Any performance testing should only be of the interface and the data structures used in that interface.

I assumed that's what @peterbourgon meant when he mentioned the Kobiashi Maru, the solution was to "redefine the problem" - the upstream problem seems to be nobody can agree on an implementation, our redefinition of a problem is just to define an interface. Re-reading I suspect he meant "insoluble problem", so that's probably just my naïvety with the uphill struggle leaking out.

Good that someone finally posted some code. My personal opinion however @progrium that the interface you proposed is too wide (just imagine all the mocks, etc), why not something like:

type Logger interface {
    With(...interface{}) Logger
    Level(Level) Logger
        
    Printf(...interface{})
    # etc...
    Map(map[string]interface{})
}

And then usage like this:

l := commons.NewLogger(os.Stdout).With(map["prefix"]["foo bar"])
# I'd like to see an example of what @progrium would use
# `With()` for, function sig doesn't give many clues

l.Level(commons.Debug).Printf("Hello Developers")
l.Level(commons.Info).Printf("Hello World")
# - Info could be implied
l.Printf("Hello wOrld")

.With can maybe also take functions like Dave Cheney's https://dave.cheney.net/2014/10/17/functional-options-for-friendly-apis

That'd allow us to configure patterns, flags, prefixes, etc, etc, etc and it would only require one general purpose config function and provide scope for expansion for extra special use-cases.

Perhaps we should pull, not push… that is, pick a logging interface that works for us (or more than one) in the commons repo, and expect that slowly, through determined, persistent effort we can work towards having our logger blessed, or is it more realistic to expect the Go team to bless their stdlib concrete logger's API as an interface?

@aybabtme

This comment has been minimized.

Show comment
Hide comment
@aybabtme

aybabtme Nov 7, 2017

A standard logging interface for common packages is the wrong approach, IMO. If a package has a complexity such that emitting information about it's internal doings is necessary, this should be done in pluggable callbacks that allow handling the events. This can then in turn be implemented with a logger, or a metrics emitter, or a tracer, or whatever else an application actually wants to do. But packages shouldn't prescribe logging semantics, they should just "do their job" and punt the problem of serializing/representing/handling non-returnable events to the application, with callbacks.

With this in mind, the problem becomes (1) "do we want to provide a specific callback type for each package" like httptrace does, or (2) "do we want to provide a generic callback type" which is where the perceived need for a standard logger seems to come from.

If commons packages are following approach (1), then this discussion's conclusion is that asking a standard logger API is the wrong question. Such an API is not needed or desirable.

In the case of (2), we're basically doing the same thing as picking a schema-less way to represent event data. Without a schema, event data is kind of becoming unreliable. Nonetheless, accepting this loss of information doesn't need losing all the information available at the time an event is emitted. One way to do it is to take key-values, which keep a "name to value" structure. While the relationship of names-to-values is kept, the meaning of the "name" can't easily be relied upon at runtime; it's string-typed programming. Aside from this key-value method, the other commonly seen (and IMO wrong) way to do it is to have printf funcs. In the key-value case, event data is well structured and can be parsed easily, despite being schema-less. In the printf case, the event data becomes an NLP problem, all structure is lost, the data is essentially useless until a human reads it and tries to make sense of it.

So I'd say that the answer to "what is a standard logger API" question is "provide a per-type callback interface instead", and if it is insisted that a generic callback API be made, that this generic API be only structured and not provide printf calls.

Here's a very rough example (alternative API aesthetics could be preferred, doesn't compile, no error handling, etc) of what I mean by (1):

// Tracer does a bunch of stuff like building spans, batching them and reporting them
// in the background. 
type Tracer struct {
    /* ... */
    monitor TracerMonitor
}

// TracerMonitor can be used by applications to handle informative 
// background events in the Tracer.
type TracerMonitor interface {
   Connecting(addr string)
   Connected(addr string)
   ErrDisconnected(addr string, err error, retryIn time.Duration)
   DroppedSpans(droppedCount int, err error)
   EmittedSpans(emittedCount int, emitLatency time.Duration)
}

// sendSpansForever runs forever in the background
func (tr *Tracer) sendSpansForever(spans <-chan Span) {
    for {
        tr.monitor.Connecting(addr)
        cc, _ := tr.dial(addr)
        tr.monitor.Connected(addr)
        var err error
        for err == nil {
            start := time.Now()
            emitted, dropped, err = sendSpanBatch(spans)
            latency := time.Since(start)
            if dropped != 0 {
                tr.monitor.DroppedSpans(dropped, err)
            }
            tr.monitor.EmittedSpans(emitted, latency)
        }
        retryIn := time.Second
        tr.monitor.ErrDisconnected(addr, err, retryIn)
        time.Sleep(retryIn)
    }
}

By default, the Tracer type here would do it's business as usual with a NopTracerMonitor implementation. But if a user wants to log its errors, or emit metrics about it, or verify that the tracer performs certain actions, they can do so by plugging in an implementation of the interface. This keeps the Tracer and its package completely clean of weird side-effect opinions like "a logger should look like this, while allowing a user to pick a logger of their choosing, or whatever else observability method they prefer, or do all kinds of other things with this data.

If instead this was done like (2):

// Tracer does a bunch of stuff like building spans, batching them and reporting them
// in the background. 
type Tracer struct {
    /* ... */
    logger Logger
}

// Logger can be used by applications to handle informative
// background events in the Tracer.
type Logger interface {
   With(keyvalues ...interface{}) Logger
   Info(string)
   Warn(string)
   Error(string)
}

func (tr *Tracer) sendSpansForever(spans <-chan Span) {
    for {
        tr.logger.With("addr", addr).Info("connecting")
        cc, _ := tr.dial(addr)
        tr.logger.With("addr", addr).Info("connected")
        var err error
        for err == nil {
            start := time.Now()
            sent, dropped, err = sendSpanBatch(spans)
            latency := time.Since(start)
            if dropped != 0 {
                tr.logger.With("dropped", dropped, "err", err).Warn("dropped spans")
            }
            tr.logger.With("emitted", dropped, "latency", latency).Info("emitted spans")
        }
        retryIn := time.Second
        tr.logger.With("addr", addr, "err", err).Error("disconnected")
        time.Sleep(retryIn)
    }
}

In this case of (2), a Logger implementation has no idea what actually happened at compile time, unless inspecting the keyvalues which I think we can agree is hacky and flaky. This information is pretty much only good for serialization at this point, and the interpretation of the structure is left to a human, down the line, when something needs to be pulled out of this data. Yet, at least by having kept the key-value mapping, the problem of parsing back the information is a well defined one. If instead this had been a Printf like API, not only would we have lost a ton of type and contextual information by picking a Logger as a solution to our problem, but also we would have lost a method to consistently retrieve the name-to-value mapping that was still available.

tl,dr: what @peterbourgon said.


A common critique to "don't provide Printf" arguments is that key-value logging is hard to read and logs are for humans to read. My answer to this is that making key-value logging human readable is easy, but making printf-loggin machine readable isn't. See humanlog as an example of this idea. Yet, still better is proper callback interfaces like (1).

aybabtme commented Nov 7, 2017

A standard logging interface for common packages is the wrong approach, IMO. If a package has a complexity such that emitting information about it's internal doings is necessary, this should be done in pluggable callbacks that allow handling the events. This can then in turn be implemented with a logger, or a metrics emitter, or a tracer, or whatever else an application actually wants to do. But packages shouldn't prescribe logging semantics, they should just "do their job" and punt the problem of serializing/representing/handling non-returnable events to the application, with callbacks.

With this in mind, the problem becomes (1) "do we want to provide a specific callback type for each package" like httptrace does, or (2) "do we want to provide a generic callback type" which is where the perceived need for a standard logger seems to come from.

If commons packages are following approach (1), then this discussion's conclusion is that asking a standard logger API is the wrong question. Such an API is not needed or desirable.

In the case of (2), we're basically doing the same thing as picking a schema-less way to represent event data. Without a schema, event data is kind of becoming unreliable. Nonetheless, accepting this loss of information doesn't need losing all the information available at the time an event is emitted. One way to do it is to take key-values, which keep a "name to value" structure. While the relationship of names-to-values is kept, the meaning of the "name" can't easily be relied upon at runtime; it's string-typed programming. Aside from this key-value method, the other commonly seen (and IMO wrong) way to do it is to have printf funcs. In the key-value case, event data is well structured and can be parsed easily, despite being schema-less. In the printf case, the event data becomes an NLP problem, all structure is lost, the data is essentially useless until a human reads it and tries to make sense of it.

So I'd say that the answer to "what is a standard logger API" question is "provide a per-type callback interface instead", and if it is insisted that a generic callback API be made, that this generic API be only structured and not provide printf calls.

Here's a very rough example (alternative API aesthetics could be preferred, doesn't compile, no error handling, etc) of what I mean by (1):

// Tracer does a bunch of stuff like building spans, batching them and reporting them
// in the background. 
type Tracer struct {
    /* ... */
    monitor TracerMonitor
}

// TracerMonitor can be used by applications to handle informative 
// background events in the Tracer.
type TracerMonitor interface {
   Connecting(addr string)
   Connected(addr string)
   ErrDisconnected(addr string, err error, retryIn time.Duration)
   DroppedSpans(droppedCount int, err error)
   EmittedSpans(emittedCount int, emitLatency time.Duration)
}

// sendSpansForever runs forever in the background
func (tr *Tracer) sendSpansForever(spans <-chan Span) {
    for {
        tr.monitor.Connecting(addr)
        cc, _ := tr.dial(addr)
        tr.monitor.Connected(addr)
        var err error
        for err == nil {
            start := time.Now()
            emitted, dropped, err = sendSpanBatch(spans)
            latency := time.Since(start)
            if dropped != 0 {
                tr.monitor.DroppedSpans(dropped, err)
            }
            tr.monitor.EmittedSpans(emitted, latency)
        }
        retryIn := time.Second
        tr.monitor.ErrDisconnected(addr, err, retryIn)
        time.Sleep(retryIn)
    }
}

By default, the Tracer type here would do it's business as usual with a NopTracerMonitor implementation. But if a user wants to log its errors, or emit metrics about it, or verify that the tracer performs certain actions, they can do so by plugging in an implementation of the interface. This keeps the Tracer and its package completely clean of weird side-effect opinions like "a logger should look like this, while allowing a user to pick a logger of their choosing, or whatever else observability method they prefer, or do all kinds of other things with this data.

If instead this was done like (2):

// Tracer does a bunch of stuff like building spans, batching them and reporting them
// in the background. 
type Tracer struct {
    /* ... */
    logger Logger
}

// Logger can be used by applications to handle informative
// background events in the Tracer.
type Logger interface {
   With(keyvalues ...interface{}) Logger
   Info(string)
   Warn(string)
   Error(string)
}

func (tr *Tracer) sendSpansForever(spans <-chan Span) {
    for {
        tr.logger.With("addr", addr).Info("connecting")
        cc, _ := tr.dial(addr)
        tr.logger.With("addr", addr).Info("connected")
        var err error
        for err == nil {
            start := time.Now()
            sent, dropped, err = sendSpanBatch(spans)
            latency := time.Since(start)
            if dropped != 0 {
                tr.logger.With("dropped", dropped, "err", err).Warn("dropped spans")
            }
            tr.logger.With("emitted", dropped, "latency", latency).Info("emitted spans")
        }
        retryIn := time.Second
        tr.logger.With("addr", addr, "err", err).Error("disconnected")
        time.Sleep(retryIn)
    }
}

In this case of (2), a Logger implementation has no idea what actually happened at compile time, unless inspecting the keyvalues which I think we can agree is hacky and flaky. This information is pretty much only good for serialization at this point, and the interpretation of the structure is left to a human, down the line, when something needs to be pulled out of this data. Yet, at least by having kept the key-value mapping, the problem of parsing back the information is a well defined one. If instead this had been a Printf like API, not only would we have lost a ton of type and contextual information by picking a Logger as a solution to our problem, but also we would have lost a method to consistently retrieve the name-to-value mapping that was still available.

tl,dr: what @peterbourgon said.


A common critique to "don't provide Printf" arguments is that key-value logging is hard to read and logs are for humans to read. My answer to this is that making key-value logging human readable is easy, but making printf-loggin machine readable isn't. See humanlog as an example of this idea. Yet, still better is proper callback interfaces like (1).

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 7, 2017

Contributor

@peterbourgon I propose that we add your logger interface in a new commons/log package and add implementations as subpackages. Would also like to see contextual logger interface and leveled logger interface added. I think your proposal and the work you and Chris did is thorough and a perfect match for the intentions of the commons libraries.

Contributor

bketelsen commented Nov 7, 2017

@peterbourgon I propose that we add your logger interface in a new commons/log package and add implementations as subpackages. Would also like to see contextual logger interface and leveled logger interface added. I think your proposal and the work you and Chris did is thorough and a perfect match for the intentions of the commons libraries.

@enrichman

This comment has been minimized.

Show comment
Hide comment
@enrichman

enrichman Nov 7, 2017

If a package has a complexity such that emitting information about it's internal doings is necessary, this should be done in pluggable callbacks that allow handling the events.

Imho these packages/utils shouldn't have a huge complexity or the need for an internal logging, so I would vote for the 1) proposed by @aybabtme, but I'm probably the less expert here. My 2¢.

Following the Apache Commons which would be the advantage of having some logs over the List lines = FileUtils.readLines(file, "UTF-8"); ?
Or I just misunderstood the whole discussion.

enrichman commented Nov 7, 2017

If a package has a complexity such that emitting information about it's internal doings is necessary, this should be done in pluggable callbacks that allow handling the events.

Imho these packages/utils shouldn't have a huge complexity or the need for an internal logging, so I would vote for the 1) proposed by @aybabtme, but I'm probably the less expert here. My 2¢.

Following the Apache Commons which would be the advantage of having some logs over the List lines = FileUtils.readLines(file, "UTF-8"); ?
Or I just misunderstood the whole discussion.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 7, 2017

Contributor

@progrium would it be possible to satisfy your ideas/requests with nested interfaces? For example, a leveled logger being a new interface that embeds logger?

Contributor

bketelsen commented Nov 7, 2017

@progrium would it be possible to satisfy your ideas/requests with nested interfaces? For example, a leveled logger being a new interface that embeds logger?

@ChrisHines

This comment has been minimized.

Show comment
Hide comment
@ChrisHines

ChrisHines Nov 7, 2017

First, thanks to @aybabtme for perfectly expressing my point of view above.

@bketelsen said:

@peterbourgon I propose that we add your logger interface in a new commons/log package and add implementations as subpackages.

When @peterbourgon and I were working on the Go proposal doc that he linked above, we discussed the idea of moving github.com/go-kit/kit/log/... into their own repo. The argument for doing so was that it would provide more visibility as a stand alone set of packages. We perceived that awareness of the go-kit log package suffered because collections like github.com/avelino/awesome-go focus on code repositories and make it difficult to list "sub"-packages. On the other hand, github.com/go-kit/kit/log is certainly popular enough that we wouldn't want to break anyone using it. We concluded that we should revisit the question when aliases dropped in Go 1.9 as that might allow us to move the packages without breaking any dependent code. So, now that 1.9 is out and in use, we can have that discussion. Our original idea was simply to move them to github.com/go-kit/log/... and your proposal above raises the obvious idea of moving them into this project instead. I am not opposed to it, but I want to consider the idea deliberately before we decide.

One point of friction to discuss is that github.com/go-kit/kit/log imports a couple of things from outside the standard library: github.com/go-stack/stack and github.com/go-logfmt/logfmt. Both of those are mine, but using them would violate the go-commons policy of only depending on the standard library or go-commons packages, and I'm not sure it makes sense to move them here as well.

@bketelsen also wrote:

Would also like to see contextual logger interface and leveled logger interface added.

In our formulation contextual logging only needs a function: https://godoc.org/github.com/go-kit/kit/log#hdr-Contextual_Loggers.

Leveled logging is also mostly just functions: https://godoc.org/github.com/go-kit/kit/log/level.

ChrisHines commented Nov 7, 2017

First, thanks to @aybabtme for perfectly expressing my point of view above.

@bketelsen said:

@peterbourgon I propose that we add your logger interface in a new commons/log package and add implementations as subpackages.

When @peterbourgon and I were working on the Go proposal doc that he linked above, we discussed the idea of moving github.com/go-kit/kit/log/... into their own repo. The argument for doing so was that it would provide more visibility as a stand alone set of packages. We perceived that awareness of the go-kit log package suffered because collections like github.com/avelino/awesome-go focus on code repositories and make it difficult to list "sub"-packages. On the other hand, github.com/go-kit/kit/log is certainly popular enough that we wouldn't want to break anyone using it. We concluded that we should revisit the question when aliases dropped in Go 1.9 as that might allow us to move the packages without breaking any dependent code. So, now that 1.9 is out and in use, we can have that discussion. Our original idea was simply to move them to github.com/go-kit/log/... and your proposal above raises the obvious idea of moving them into this project instead. I am not opposed to it, but I want to consider the idea deliberately before we decide.

One point of friction to discuss is that github.com/go-kit/kit/log imports a couple of things from outside the standard library: github.com/go-stack/stack and github.com/go-logfmt/logfmt. Both of those are mine, but using them would violate the go-commons policy of only depending on the standard library or go-commons packages, and I'm not sure it makes sense to move them here as well.

@bketelsen also wrote:

Would also like to see contextual logger interface and leveled logger interface added.

In our formulation contextual logging only needs a function: https://godoc.org/github.com/go-kit/kit/log#hdr-Contextual_Loggers.

Leveled logging is also mostly just functions: https://godoc.org/github.com/go-kit/kit/log/level.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 7, 2017

Contributor

@ChrisHines it brings up a good discussion point, moving something here that has dependencies could create quite a cascade of required moves. Or we can reconsider the dependencies. we could create separate repositories for packages that have external dependencies and treat them differently. very open to thoughts and opinions here. Either way, I want to treat dependencies as a big issue, not a casual one.

Contributor

bketelsen commented Nov 7, 2017

@ChrisHines it brings up a good discussion point, moving something here that has dependencies could create quite a cascade of required moves. Or we can reconsider the dependencies. we could create separate repositories for packages that have external dependencies and treat them differently. very open to thoughts and opinions here. Either way, I want to treat dependencies as a big issue, not a casual one.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 7, 2017

Contributor

@ChrisHines I opened #4 to discuss external dependencies.

Contributor

bketelsen commented Nov 7, 2017

@ChrisHines I opened #4 to discuss external dependencies.

@ncdc

This comment has been minimized.

Show comment
Hide comment
@ncdc

ncdc commented Nov 7, 2017

@flowchartsman

This comment has been minimized.

Show comment
Hide comment
@flowchartsman

flowchartsman Nov 7, 2017

+1 to standardizing on callback APIs (if anything) rather than a blessed logging interface.

flowchartsman commented Nov 7, 2017

+1 to standardizing on callback APIs (if anything) rather than a blessed logging interface.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen
Contributor

bketelsen commented Nov 7, 2017

@flowchartsman

This comment has been minimized.

Show comment
Hide comment
@flowchartsman

flowchartsman Nov 8, 2017

I'm not sure how much I like that interface. If anything, I should be able to pass the library a callback that is something like:

// in package eventlog (or whatever)
type Message struct {
    //whatever
}

type EventCB func(Message) error

// in my code
myLogHandler := func(m Message) error {
  //handle M
}

Which the library can either choose to implement globally

library.RegisterLoggingCallback(myLogHandler)

or on a type basis

my foo := library.NewFoo(stuff)
foo.RegisterLoggingCallback(myLogHandler)

flowchartsman commented Nov 8, 2017

I'm not sure how much I like that interface. If anything, I should be able to pass the library a callback that is something like:

// in package eventlog (or whatever)
type Message struct {
    //whatever
}

type EventCB func(Message) error

// in my code
myLogHandler := func(m Message) error {
  //handle M
}

Which the library can either choose to implement globally

library.RegisterLoggingCallback(myLogHandler)

or on a type basis

my foo := library.NewFoo(stuff)
foo.RegisterLoggingCallback(myLogHandler)
@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

@Alaska wouldn't you also need to register handlers too? so the event package thing has a slice of registered handlers and calls them when a Message is published?

Contributor

bketelsen commented Nov 8, 2017

@Alaska wouldn't you also need to register handlers too? so the event package thing has a slice of registered handlers and calls them when a Message is published?

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

how is this different from a channel? If you "subscribe" you get a channel, and use a function to handle each message. If you register a "handler" with your event code, it's the same thing.

Contributor

bketelsen commented Nov 8, 2017

how is this different from a channel? If you "subscribe" you get a channel, and use a function to handle each message. If you register a "handler" with your event code, it's the same thing.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

it's also worth noting that these 2 concepts aren't mutually exclusive. It's possible (but I'm not yet suggesting it) that we could have an event interface, and the logger is just one implementation of it that subscribes/handles events.

(edit) or the converse: log interface emits events and another layer will send them via channel or callback function.

The proposal by @ChrisHines and @peterbourgon doesn't require that there's any sort of io writer. It's just an interface, so an implementation could accept callback functions, or create a channel of event messages.

Contributor

bketelsen commented Nov 8, 2017

it's also worth noting that these 2 concepts aren't mutually exclusive. It's possible (but I'm not yet suggesting it) that we could have an event interface, and the logger is just one implementation of it that subscribes/handles events.

(edit) or the converse: log interface emits events and another layer will send them via channel or callback function.

The proposal by @ChrisHines and @peterbourgon doesn't require that there's any sort of io writer. It's just an interface, so an implementation could accept callback functions, or create a channel of event messages.

@flowchartsman

This comment has been minimized.

Show comment
Hide comment
@flowchartsman

flowchartsman Nov 8, 2017

You can probably make arguments for either side.

Having said that, I'm not a fan of having a "give me a channel" method, since that approach would place the responsibility of provisioning the channel and fanning out in the case of multiple calls outside of the control of the user. A callback approach, on the other hand, would allow the user to do whatever they wanted with emitted events, such as:

  1. handle it immediately
  2. place it on a synchronous channel for logging
  3. place it on a buffered channel according to their needs
  4. etc.

I suppose you could standardize on forcing the user to pass in a chan eventlog.Message, provisioned however they like, though with a callback at least they would be dealing with potential blocking issues (and resultant debugging/stacktraces) that occur in their own code, rather than some arbitrary point in a library.

flowchartsman commented Nov 8, 2017

You can probably make arguments for either side.

Having said that, I'm not a fan of having a "give me a channel" method, since that approach would place the responsibility of provisioning the channel and fanning out in the case of multiple calls outside of the control of the user. A callback approach, on the other hand, would allow the user to do whatever they wanted with emitted events, such as:

  1. handle it immediately
  2. place it on a synchronous channel for logging
  3. place it on a buffered channel according to their needs
  4. etc.

I suppose you could standardize on forcing the user to pass in a chan eventlog.Message, provisioned however they like, though with a callback at least they would be dealing with potential blocking issues (and resultant debugging/stacktraces) that occur in their own code, rather than some arbitrary point in a library.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

I think we've gone too far in the weeds. We can create a solid Logger interface and have implementations that write to disk, to network, to channels, call functions registered as callbacks, write to [event streaming service du jour]. Let's start with the interface - maybe considering that calling it "Logger" is a misnomer.

Contributor

bketelsen commented Nov 8, 2017

I think we've gone too far in the weeds. We can create a solid Logger interface and have implementations that write to disk, to network, to channels, call functions registered as callbacks, write to [event streaming service du jour]. Let's start with the interface - maybe considering that calling it "Logger" is a misnomer.

@flowchartsman

This comment has been minimized.

Show comment
Hide comment
@flowchartsman

flowchartsman Nov 8, 2017

Sure, but this has already been done several times. Go-kit has settled on the one-method logger. Do we want more than this? If so, what levels do we want to support? Do we want to provide convenience methods for each one where something like LevelXm(stringVal) maps to a LevelX("msg", stringVal) call?
How do we handle users and library authors that see no need for anything more than Info() and Debug()? All of these concerns and prior art just kind of go away when you have a callback approach that leaves the handling of various event types up to the user. Then it is the user that decides what is and is not an "Error" versus a "Warning", if those distinctions even apply to them.

flowchartsman commented Nov 8, 2017

Sure, but this has already been done several times. Go-kit has settled on the one-method logger. Do we want more than this? If so, what levels do we want to support? Do we want to provide convenience methods for each one where something like LevelXm(stringVal) maps to a LevelX("msg", stringVal) call?
How do we handle users and library authors that see no need for anything more than Info() and Debug()? All of these concerns and prior art just kind of go away when you have a callback approach that leaves the handling of various event types up to the user. Then it is the user that decides what is and is not an "Error" versus a "Warning", if those distinctions even apply to them.

@rakyll

This comment has been minimized.

Show comment
Hide comment
@rakyll

rakyll Nov 8, 2017

I think it is too early to focus on designing a logger interface but we can benefit a lot from agreeing on a data model for a logging entry. What goes into a logging entry? Message, timestamp, severity level, labels, etc? Then, we can suggest libraries to produce log messages in this specific format and communicate them with hooks. Then, a Logger interface can be achieved once we are confident about the data model. The primary goal should be achieving a data model to represent log entries.

rakyll commented Nov 8, 2017

I think it is too early to focus on designing a logger interface but we can benefit a lot from agreeing on a data model for a logging entry. What goes into a logging entry? Message, timestamp, severity level, labels, etc? Then, we can suggest libraries to produce log messages in this specific format and communicate them with hooks. Then, a Logger interface can be achieved once we are confident about the data model. The primary goal should be achieving a data model to represent log entries.

@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon Nov 8, 2017

One clear outcome of the logging discussion earlier this year is that there is no universal data model for log entries.

peterbourgon commented Nov 8, 2017

One clear outcome of the logging discussion earlier this year is that there is no universal data model for log entries.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

I have to agree with @peterbourgon. If you want to have a data model that includes named fields, it fits on a paired key/value interface well. You just use known keys.

const SeverityKey = "severity"
type SeverityLevel string

type StructuredLogMessage struct {
    Severity SeverityLevel
    ... others elided

}

func NewStructuredLogMessage(kvs ...interface{}) StructuredLogMessage {
   // search for keys with the value "severity"
  // set severity to the value of that key
 // return the StructuredLogMessage
}

This still fits with the original Logger interface. It's just a layer on top of it. The added benefit is that people may start to use well-known keys for their k/v logging.

Contributor

bketelsen commented Nov 8, 2017

I have to agree with @peterbourgon. If you want to have a data model that includes named fields, it fits on a paired key/value interface well. You just use known keys.

const SeverityKey = "severity"
type SeverityLevel string

type StructuredLogMessage struct {
    Severity SeverityLevel
    ... others elided

}

func NewStructuredLogMessage(kvs ...interface{}) StructuredLogMessage {
   // search for keys with the value "severity"
  // set severity to the value of that key
 // return the StructuredLogMessage
}

This still fits with the original Logger interface. It's just a layer on top of it. The added benefit is that people may start to use well-known keys for their k/v logging.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

@Alaska go-kit's log package has a LoggerFunc() that does what you suggest above. Doesn't this meet your requirements?

https://github.com/go-kit/kit/blob/master/log/log.go#L130

It satisfies the Logger interface, and it uses functions as callbacks.

Contributor

bketelsen commented Nov 8, 2017

@Alaska go-kit's log package has a LoggerFunc() that does what you suggest above. Doesn't this meet your requirements?

https://github.com/go-kit/kit/blob/master/log/log.go#L130

It satisfies the Logger interface, and it uses functions as callbacks.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

and here's a silly-hacked-together-late-night implementation of the channel version, still satisfying the Logger interface:
https://gist.github.com/bketelsen/04363b53fa851277e25b7b243101003d

Contributor

bketelsen commented Nov 8, 2017

and here's a silly-hacked-together-late-night implementation of the channel version, still satisfying the Logger interface:
https://gist.github.com/bketelsen/04363b53fa851277e25b7b243101003d

@rakyll

This comment has been minimized.

Show comment
Hide comment
@rakyll

rakyll Nov 8, 2017

A vague ...interface{} whatever you can pass is neither a user nor a logger implementer-friendly approach. That approach is only escalating the complexity to the user of the interface. A vague logger interface has so little benefit to be a central dependency for everyone who wants to log.

rakyll commented Nov 8, 2017

A vague ...interface{} whatever you can pass is neither a user nor a logger implementer-friendly approach. That approach is only escalating the complexity to the user of the interface. A vague logger interface has so little benefit to be a central dependency for everyone who wants to log.

@peterbourgon

This comment has been minimized.

Show comment
Hide comment
@peterbourgon

peterbourgon Nov 8, 2017

It’s definitely a compromise approach, but its virtues (and drawbacks) for both users and implementers were pretty well enumerated by @aybabtme above.

peterbourgon commented Nov 8, 2017

It’s definitely a compromise approach, but its virtues (and drawbacks) for both users and implementers were pretty well enumerated by @aybabtme above.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 8, 2017

Contributor

@rakyll this is what we already have in the stdlib log package:
https://github.com/golang/go/blob/master/src/log/log.go#L184

Contributor

bketelsen commented Nov 8, 2017

@rakyll this is what we already have in the stdlib log package:
https://github.com/golang/go/blob/master/src/log/log.go#L184

@rakyll

This comment has been minimized.

Show comment
Hide comment
@rakyll

rakyll Nov 8, 2017

@bketelsen, I find it hard to follow. Standard library's logger only produces formatted strings. It is one of the few cases on the planet where ...interface{} is an established and well understood API. The proposed logging API is likely to do more: string formatting, adding labels, modifying prefixes etc. None of this behavior will be represented in the interface as far as I understand. It is a burden (a) for the implementors to understand which options it needs to support, (b) for the user to understand which implementations support what options.

rakyll commented Nov 8, 2017

@bketelsen, I find it hard to follow. Standard library's logger only produces formatted strings. It is one of the few cases on the planet where ...interface{} is an established and well understood API. The proposed logging API is likely to do more: string formatting, adding labels, modifying prefixes etc. None of this behavior will be represented in the interface as far as I understand. It is a burden (a) for the implementors to understand which options it needs to support, (b) for the user to understand which implementations support what options.

@travisjeffery

This comment has been minimized.

Show comment
Hide comment
@travisjeffery

travisjeffery Nov 8, 2017

Catching up: I think just having a logger interface would have a similar effect to gofmt. People in other communities can't agree on the best way to format code but it's not a problem in Go thanks to gofmt. Even if initially you didn't like how it formats code it's the way to format code and eventually you see the overall benefit. Same situation here. All the decent approaches have tradeoffs. The larger benefit comes from picking anyone of them.

That being said I think this interface has been shown to work with go-kit/log, its logger implementations, and projects using it.

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

Having a type would be nice, of course, but it'd cost a bulkier API wouldn't it? Most users would probably write their own helper function to create the the log message. Which in a way diminishes having a common interface.

travisjeffery commented Nov 8, 2017

Catching up: I think just having a logger interface would have a similar effect to gofmt. People in other communities can't agree on the best way to format code but it's not a problem in Go thanks to gofmt. Even if initially you didn't like how it formats code it's the way to format code and eventually you see the overall benefit. Same situation here. All the decent approaches have tradeoffs. The larger benefit comes from picking anyone of them.

That being said I think this interface has been shown to work with go-kit/log, its logger implementations, and projects using it.

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

Having a type would be nice, of course, but it'd cost a bulkier API wouldn't it? Most users would probably write their own helper function to create the the log message. Which in a way diminishes having a common interface.

@akutz

This comment has been minimized.

Show comment
Hide comment
@akutz

akutz Nov 8, 2017

Hi @travisjeffery,

So I worked on a project called gournal -- a wrapper for several, disparate Go logging frameworks. In doing so I created several benchmarks to try and get Gournal to have zero overhead. I was successful, but in doing so I learned that the real problem at the crux of a lot of the logging libraries is their reliance on interface{} and variadic functions. The former relies on dynamic dispatch and the latter allocates slices to handle params.

I'd much rather see this:

type Logger interface {	
    Log(ctx context.Context, msg string) error
}

Then leave it up to the implementation to extract possible keys out of the Go Context in order to provide structured logging. However, in the event that no keys are present or the context is nil, at least the base implementation can have zero overhead since it's just logging a string.

akutz commented Nov 8, 2017

Hi @travisjeffery,

So I worked on a project called gournal -- a wrapper for several, disparate Go logging frameworks. In doing so I created several benchmarks to try and get Gournal to have zero overhead. I was successful, but in doing so I learned that the real problem at the crux of a lot of the logging libraries is their reliance on interface{} and variadic functions. The former relies on dynamic dispatch and the latter allocates slices to handle params.

I'd much rather see this:

type Logger interface {	
    Log(ctx context.Context, msg string) error
}

Then leave it up to the implementation to extract possible keys out of the Go Context in order to provide structured logging. However, in the event that no keys are present or the context is nil, at least the base implementation can have zero overhead since it's just logging a string.

@corylanou

This comment has been minimized.

Show comment
Hide comment
@corylanou

corylanou Nov 8, 2017

I've looked at this issue over the last year in depth, and one of the things I've concluded is that the paradigm of logging is actually the problem. It's also why we'll never come to one interface to rule them all. Let me explain.

Many of us are logging for different reasons.

Metrics

Any time we talk about structured logging, we are likely also talking about metrics. This data is something we typically want fed into a third party analytics package to help us understand how the application is performing.

Event/Alert data

Messages like "can't write to database" aren't useful in a log, they are useful if they are sent to a notification/alerting system. These types of messages don't necessarily fit the Metrics paradigm.

Debugging/Info

Some messages are simply used for debugging or informational such as "database started successfully" etc.

As you can see, I've already identified 3 distinct use cases for logging. Sometimes, the package that is logging only cares about one of them, sometimes all of them. The thought that we can find one magic interface to satisfy all those needs means that we are constantly trying to fit a square in a circle.

So, I'm not suggesting we don't solve this, instead, I'm suggesting that we stop thinking about logging. What we are really talking about is communication between packages. Importing a package, only to have to provide it their version of a logger (or even worse a specific logger like glog or zap, etc) creates a really bad experience. You now have a package making application level decisions about what/where output from your application goes. This is not acceptable.

Instead, let's talk about using injection or callbacks to communicate from the packages we import. This means we don't depend on any logging packages. We can also then decide what to do with that information (send it to an alerting system, send it to an analytics package, etc.).

Much in the same way we are forced to think about how we want to handle every error return from any function/method we call, we should also give that same level of thought to the data that the package is trying to communicate to us. The logging paradigm has made us a bit lazy imo as developers and just assuming if we log it, our job is done. I don't believe that is enough. I believe we need to think about what type of data/communication is being sent to us by the package, and what our specific application should do with it. I think you will find that each application has a different need for the package that it is importing. That's why we should not allow packages to make application decisions.

In Summary

Stop logging in your packages, start communicating.

corylanou commented Nov 8, 2017

I've looked at this issue over the last year in depth, and one of the things I've concluded is that the paradigm of logging is actually the problem. It's also why we'll never come to one interface to rule them all. Let me explain.

Many of us are logging for different reasons.

Metrics

Any time we talk about structured logging, we are likely also talking about metrics. This data is something we typically want fed into a third party analytics package to help us understand how the application is performing.

Event/Alert data

Messages like "can't write to database" aren't useful in a log, they are useful if they are sent to a notification/alerting system. These types of messages don't necessarily fit the Metrics paradigm.

Debugging/Info

Some messages are simply used for debugging or informational such as "database started successfully" etc.

As you can see, I've already identified 3 distinct use cases for logging. Sometimes, the package that is logging only cares about one of them, sometimes all of them. The thought that we can find one magic interface to satisfy all those needs means that we are constantly trying to fit a square in a circle.

So, I'm not suggesting we don't solve this, instead, I'm suggesting that we stop thinking about logging. What we are really talking about is communication between packages. Importing a package, only to have to provide it their version of a logger (or even worse a specific logger like glog or zap, etc) creates a really bad experience. You now have a package making application level decisions about what/where output from your application goes. This is not acceptable.

Instead, let's talk about using injection or callbacks to communicate from the packages we import. This means we don't depend on any logging packages. We can also then decide what to do with that information (send it to an alerting system, send it to an analytics package, etc.).

Much in the same way we are forced to think about how we want to handle every error return from any function/method we call, we should also give that same level of thought to the data that the package is trying to communicate to us. The logging paradigm has made us a bit lazy imo as developers and just assuming if we log it, our job is done. I don't believe that is enough. I believe we need to think about what type of data/communication is being sent to us by the package, and what our specific application should do with it. I think you will find that each application has a different need for the package that it is importing. That's why we should not allow packages to make application decisions.

In Summary

Stop logging in your packages, start communicating.

@ChrisHines

This comment has been minimized.

Show comment
Hide comment
@ChrisHines

ChrisHines Nov 8, 2017

I agree with @corylanou above. As I've said many times, logging is an application concern. Widely shared public packages shouldn't log. They might want to provide hooks for an application to find out about internal events, which the application can then handle how it wants.

So, what is the goal here? I see a few possibilities:

  1. Bless an existing log package.
  2. Design a log package that improves on the state of the art (on some axis).
  3. Decide how other packages within go-commons will interact with the logging needs of applications that import them.
  4. ???

My thoughts on the above:

  1. This assumes we know the needs of applications that haven't been written yet. I don't think there is one log package that is best for all apps. Maybe there is some appetite for a short list with guidance.
  2. I'm sure it could be done, but there are already many good choices in the Go ecosystem, so I'm not sure it would add much value.
  3. This is important and my recommendation is that each package in go-commons provide the appropriate richly-typed hooks (which might be none, depending on what the package does).
  4. What have I missed?

ChrisHines commented Nov 8, 2017

I agree with @corylanou above. As I've said many times, logging is an application concern. Widely shared public packages shouldn't log. They might want to provide hooks for an application to find out about internal events, which the application can then handle how it wants.

So, what is the goal here? I see a few possibilities:

  1. Bless an existing log package.
  2. Design a log package that improves on the state of the art (on some axis).
  3. Decide how other packages within go-commons will interact with the logging needs of applications that import them.
  4. ???

My thoughts on the above:

  1. This assumes we know the needs of applications that haven't been written yet. I don't think there is one log package that is best for all apps. Maybe there is some appetite for a short list with guidance.
  2. I'm sure it could be done, but there are already many good choices in the Go ecosystem, so I'm not sure it would add much value.
  3. This is important and my recommendation is that each package in go-commons provide the appropriate richly-typed hooks (which might be none, depending on what the package does).
  4. What have I missed?
@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 9, 2017

Contributor

I think that we should agree on two things:

  1. Libraries shouldn't log. commons libs will not log, but instead emit notifications that can be consumed or ignored by calling code.
  2. Loggers need to exist for commands

Let's create an event interface/lib for 1, and a logger for 2.

If we can agree on that, I'd propose the go-kit logger for our command logger.

Contributor

bketelsen commented Nov 9, 2017

I think that we should agree on two things:

  1. Libraries shouldn't log. commons libs will not log, but instead emit notifications that can be consumed or ignored by calling code.
  2. Loggers need to exist for commands

Let's create an event interface/lib for 1, and a logger for 2.

If we can agree on that, I'd propose the go-kit logger for our command logger.

@DaKine23

This comment has been minimized.

Show comment
Hide comment
@DaKine23

DaKine23 Nov 9, 2017

Somehow independent of the Interface or API. I would like to see standardized outputs based on something official like https://tools.ietf.org/html/rfc5424. Have my own implementation for my projects and would love to see the general pattern spread.

DaKine23 commented Nov 9, 2017

Somehow independent of the Interface or API. I would like to see standardized outputs based on something official like https://tools.ietf.org/html/rfc5424. Have my own implementation for my projects and would love to see the general pattern spread.

@bketelsen

This comment has been minimized.

Show comment
Hide comment
@bketelsen

bketelsen Nov 9, 2017

Contributor

I have created https://github.com/go-commons/event and https://github.com/go-commons/log I am closing this issue and we can continue in the appropriate repositories.

Contributor

bketelsen commented Nov 9, 2017

I have created https://github.com/go-commons/event and https://github.com/go-commons/log I am closing this issue and we can continue in the appropriate repositories.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment