Standardization around logging and related concerns

[Peter Bourgon]

Brian Ketelsen made a Tweet recently

https://twitter.com/bketelsen/status/820768241849077760

which spawned an interesting proto-discussion about logging, tracing,
error reporting, and metrics, with Sameer, Rakyll, Dave, and other
titans of industry. We quickly outgrew the limits of Twitter, so I've
started this thread to continue the conversation.

Here are the questions as I see them:

1) What would a "standardized" logging interface look like?
2) How would that interface interact with related concerns e.g.
context, tracing, instrumentation?

—

re: point 1, Chris Hines and I have spent a lot of time and considered
energy on the subject over the last several years (!) — and the
artifact of that work has been the Go kit logger interface[0], and the
concomitant talk "The Hunt for a Logger Interface"[1].

The Logger interface in particular I am very proud of. The advantages
of its small size should be self-evident. But after many years of
production [ab]use, it's also proven to be extremely intuitive to use
at callsites, composable with both contexts[2] and leveled logging[3]
on an opt-in basis, and as far as I'm aware it's as performant as it
can possibly be, given the constraints of interface{}.

I'm sure there are situations where it's not perfect, and I'm happy to
discuss those, but I've been totally convinced that it's the right
model for a general-purpose structured logging interface.

[0] https://godoc.org/github.com/go-kit/kit/log#Logger
[1] http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1
[2] https://godoc.org/github.com/go-kit/kit/log#Context
[3] https://godoc.org/github.com/go-kit/kit/log/experimental_level

[Sameer Ajmani]

+Aiden Scandella, Uber

On the performance end, Uber's zap claims some impressive numbers:
https://github.com/uber-go/zap/blob/master/README.md

This appears to support similar key-values to go-kit.  It would be good to understand the performance differences.

I'd like any standard log API to impose low performance penalty. While we can ask people to avoid logging in high-performance code, it's better to be fast by default.  In particular, can we develop an API that avoids making any allocations in the common cases?

--
You received this message because you are subscribed to the Google Groups "golang-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-dev+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Peter Bourgon]

As far as I understand it, zap achieves its impressive performance
numbers by exposing a typed API. That is,

logger.Info("Failed to fetch URL.",
zap.String("url", url), // <-- these bits
zap.Int("attempt", tryNum),
zap.Duration("backoff", sleepFor),
)

I don't judge the cost of losing a generalized and minimal API surface
to be worth the benefit of zero allocations, at least for the general
case. But, reasonable people may of course disagree.

[Chris Hines]

I spent some time studying Zap last June running its benchmarks and comparing them to other structured logging packages. It achieves its performance by two essential means.

1. Zap accepts log data as a ...Field rather than ...interface{}. Type field is defined so that it can carry most primitive values without an additional allocation (see below). As a result, calling one of the log methods must only allocate for the slice, but not for each element as a ...interface{} does (especially since the implementation change to interfaces made in Go 1.4).

type Field struct {
    key       string
    fieldType fieldType
    ival      int64
    str       string
    obj       interface{}
}

2. Zap also has low allocation encoders for producing the final output text. The benchmarks published by the zap team that got everyone's attention were based on a JSON encoding. Most of the competition uses the standard library encoding/json and it is not a good fit for the task of producing this type of output. Logrus/log15/go-kit all currently convert the slice of k/v pairs into a map[string]interface{} and then pass this to encoding/json. This sequence does a lot of allocation for each log record. Zap avoids this overhead by providing a JSON encoder tailored to its use case. This difference provides the majority of the performance gains relative to other packages.

Based on the above findings I did a POC implementation of a low allocation JSON encoder for the go-kit log.Logger interface (code here: https://github.com/go-kit/kit/blob/json-log/log/json_logger.go#L40) that my benchmarks showed was competitive with zap up to the overhead of the allocations imposed by the ...interface{} signature.

My benchmarking (using an extended version of this code https://gist.github.com/ChrisHines/5c32bd11dd16db713776) last June produced the following results:

name            old time/op    new time/op    delta
GokitLogfmt-4     3.35µs ± 1%    3.42µs ± 2%   +2.11%   (p=0.000 n=10+10)
Log15Logfmt-4     17.9µs ± 1%    17.7µs ± 1%   -1.19%   (p=0.000 n=9+9)
LogrusLogfmt-4    12.8µs ± 1%    13.0µs ± 1%   +1.09%   (p=0.000 n=10+9)
GokitJSON-4       10.0µs ± 0%     3.5µs ± 0%  -64.80%   (p=0.000 n=9+10)
Log15JSON-4       18.9µs ± 1%    18.8µs ± 0%   -0.39%   (p=0.027 n=10+9)
LogrusJSON-4      18.3µs ± 1%    18.4µs ± 0%     ~      (p=0.074 n=9+10)
ZapJSON-4         1.57µs ± 1%    1.57µs ± 0%     ~      (p=0.741 n=9+9)


name            old alloc/op   new alloc/op   delta
GokitLogfmt-4       320B ± 0%      320B ± 0%     ~     (all samples are equal)
Log15Logfmt-4     1.96kB ± 0%    1.96kB ± 0%     ~     (all samples are equal)
LogrusLogfmt-4    1.62kB ± 0%    1.62kB ± 0%     ~     (all samples are equal)
GokitJSON-4       1.12kB ± 0%    0.32kB ± 0%  -71.43%  (p=0.000 n=10+10)
Log15JSON-4       1.81kB ± 0%    1.81kB ± 0%     ~     (all samples are equal)
LogrusJSON-4      2.30kB ± 0%    2.30kB ± 0%     ~     (all samples are equal)
ZapJSON-4           192B ± 0%      192B ± 0%     ~     (all samples are equal)


name            old allocs/op  new allocs/op  delta
GokitLogfmt-4       11.0 ± 0%      11.0 ± 0%     ~     (all samples are equal)
Log15Logfmt-4       45.0 ± 0%      45.0 ± 0%     ~     (all samples are equal)
LogrusLogfmt-4      27.0 ± 0%      27.0 ± 0%     ~     (all samples are equal)
GokitJSON-4         32.0 ± 0%      11.0 ± 0%  -65.62%  (p=0.000 n=10+10)
Log15JSON-4         40.0 ± 0%      40.0 ± 0%     ~     (all samples are equal)
LogrusJSON-4        43.0 ± 0%      43.0 ± 0%     ~     (all samples are equal)
ZapJSON-4           1.00 ± 0%      1.00 ± 0%     ~     (all samples are equal)

The only change between old and new was the use of my POC JSON encoder instead of encoding/json with the GokitJSON benchmarks. I think it is noteworthy that the custom JSON encoder got us within a factor of ~2x of Zap and also that for go-kit it brought JSON performance on par with logfmt performance which already has a well suited encoder. Having contributed to Log15 and also having spent a non-trivial amount of time studying Logrus I think it is fair to say that using a custom JSON encoder with those two packages would produce similarly dramatic gains.

I believe that the remaining performance delta is in the allocations the compiler introduces for each element of the ...interface{} that Zap avoids for most values by using a ...Field. As Peter pointed out, however, accepting ...Field results in noisier call sites and a less general API.

Chris

[Brian Ketelsen]

Thanks for starting the thread Peter.

I want to start by defining a particular and singular problem definition:

Libraries that I consume frequently define their own loggers, don’t expose a way for me to override the logger, or worse, they use a non-standard logger.

Rather than argue about whether libraries should log (it’s a losing proposition to argue this), I want to explore the possibility of creating an interface that would satisfy the needs of most people who want to log. I believe that people choose not to use Go’s logging for the following reasons, which are not empirically confirmed, but intuited:

1) No leveled logging
2) No structured logging

There may be others, but I think these are the top two reasons, based on personal observation.

Therefore I posit that if there existed an interface that was promoted to “standard library” status by Go, it would be easier to convince library authors to log to that interface rather than choosing any of the specific implementations. I don’t believe any interface can succeed without some sort of official acceptance by Go as an entity.

I would also argue that given such an interface it would be relatively easy to adapt all or most existing libraries for logging to meet that interface.

We would all benefit from this effort, because we’d be able to control the output and format of logs from our own main() all the way through to the libraries that we import.

I’m not proposing a full implementation of this interface, rather just the existence and *more importantly* promotion of the interface to standard library.

Peter and Chris: It looks like you’ve invested a lot of time and thought into these concerns. How do you feel about having a single interface as a proposal rather than an implementation like you’ve shown? I don’t have any complaints about go-kit’s logger interface or implementation, but I believe we’ll gain more traction by focusing on an interface rather than one specific implementation.

Thanks all for joining the discussion. I’m also interested in how we can promote and encourage adoption were we able to create a standard interface.

Best,

Brian

[Josh Bleecher Snyder]

Some ideas for how the compiler+runtime could reduce the number of
allocations required to use a go-kit-style logging API:

* Make putting small numbers in interfaces allocation-free. [0]
* Make putting constant strings in interfaces allocation-free. [1]
* Partial inlining [2] could help reduce the cost of discarded leveled
logging, although it'd require a bit more structure than the current
go-kit log interface. The idea is that the "ignore due to log level?"
check at the beginning of the log function gets inlined, and the call
stack--with concomitant allocation--never gets set up if it is not
necessary.

These are still no guarantee of alloc-free logging here. That's
probably impossible with the go-kit logging API. But I suspect it'd
help a lot.

-josh

[0] https://github.com/golang/go/issues/17725
[1] https://github.com/golang/go/issues/18704
[2] https://github.com/golang/go/issues/17566#issuecomment-255793777

[Jaana Burcu Dogan]

Thanks for the thread!

I would like to summarize the main blockers I have experienced or given feedback about for the past many years. I strongly encourage us to consider them all before finalizing this discussion. Some items are a repetition of what has already mentioned.

1) No portability

Standard library logging package is not backend agnostic. Hence, the large majority needed to establish new logging clients rather than implementing an interface. The Go ecosystem is entirely fragmented. Library authors cannot publish portable code.

2) No structured logging, no contextual logging

It is a requirement to log arbitrary key-values that provides context about the call site, such as request ID, user identifier, trace ID and so on. OTOH, most cloud logging providers are by default structured logging services that provide filtering and ordering by structured values. It is a nightmare for portability to having to design proprietary APIs for these providers.

3) No leveled logging

Similar to the case for the structured logging but levels are more established as an industry standard. The more we fight this the more new standards are going to happen. We need to find a minimal solution without introducing more APIs. I have been thinking that a level might be passed as a key-value pair if we want to keep logging primarily unleveled. So a level is just another key-value, the backend can interpret logs without level as info level if it enforces leveling.

4) The overwhelmingly increasing diagnostics/metrics related APIs

We keep talking about establishing more standards in the scope of diagnostics such as tracing. We wouldn't want us to end up having to pass 5 different clients to every call to get this done. We should care about the verbosity and how these packages scale from the user's perspective.

5) Not blocking and networking friendly

Our logging APIs are not friendly if logger is blocking and doing some networking for each write. This is not a typical case but let's consider if we need a context arg when logging to support blocking and networking loggers.

6) Performance

The case for zap and all that is said earlier on this thread.

On Wed, Jan 18, 2017 at 8:51 AM, Aiden Scandella <ai...@uber.com> wrote:

For what it's worth, many developers at Uber agree with Peter on the ergonomics/verbosity of specifying types at call sites. A "sugared" logger is in the works (and already being used in our service framework) that provides variadic key/value pairs of eface: https://github.com/uber-go/zap/pull/185/files#diff-1b63c741609271aaf2cacbe869f304c8R68

>>>
>>> --
>>> You received this message because you are subscribed to the Google Groups
>>> "golang-dev" group.
>>> To unsubscribe from this group and stop receiving emails from it, send an
>>> email to golang-dev+unsubscribe@googlegroups.com.
>>> For more options, visit https://groups.google.com/d/optout.
>
> --
> You received this message because you are subscribed to the Google Groups "golang-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to golang-dev+unsubscribe@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Daniel Theophanes]

Rather than argue about whether libraries should log (it’s a losing proposition to argue this),

I see logging, tracing, and error contexts as very much related. A sql driver package I'm working right uses an internal leveled logger, but what it really needs is better tracing (API, education via posts, interop between trace, logs, and errors).  I think any standardized design should combine each of these. I like what Dave did with github.com/pkg/errors in many aspects, but I'd rather wrap a contextual log trace, not a stack trace. It would be even better if a the sql package could instrument certain calls with traces, and optionally allow drivers to verbosely fill in additional operations to that trace. Then an error produced by the driver could contain the entire logical call and logical log of events if desired.

[Dave Cheney]

Hello,

By my informal survey, logging in Go applications follows three routes:

- Using some form of fmt.Printf
- Using functions from the log package
- Declaring a log variable at a package level

The first is my preferred approach as it follows the 12 factor
doctrine, but so unpopular as to consider it out of scope for this
proposal.

The second is unpopular as the log package in the standard library is
considered inadequate for developer's needs. It could be because
people feel that the logger is not flexible enough, and see a pattern
of closed proposal to add features to it as justification for this
view, or it could just be that they've taken then logging style from
their previous language and applied to whole cloth to go. Who knows,
the boat has left the jetty on this one.

This leaves a common pattern of declaring one or more private
variables to hold a per package logger, a la

package foo

import “mylogger”

var log = mylogger.GetLogger(“github.com/project/foo”)

This pattern creates two issues.

1. There is a direct source level dependency between package foo
package mylogger. A consumer of package foo is forced to take a
dependency on mylogger.
2. Which leads to projects composed of packages using multiple logging
libraries, -or- fiefdoms of projects who can only consume packages
that use their particular logging library.

It is the first problem that leads to the second and thus Peter, Brian
and Cory's complaints.

I've tried to codify my solution to this problem with these recommendations.

- libraries should not log error messages, they should return error values
- if libraries need to log _informational_ messages, they should do so
using a value passed in during construction, usually stored in their
structure. I believe this is what Brian refers to when he says "A
common log interface", the type of the logger stored in your type and
availble to methods to use to log informational mesages.
- don't log in free functions, return errors
- don't use package level logger variables, they create tight source
level coupling, which is how we got here in the first place.

Thanks

Dave

> --
> You received this message because you are subscribed to the Google Groups
> "golang-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an

> email to golang-dev+...@googlegroups.com.

[Chris Hines]

Daniel,

I think you are right that there is a relationship of some sort between error handling and logging, maybe even a kind of duality. Your post reminded me of a discussion that took place in one of the pkg/errors issues that requested adding a set of context values to errors. My comment on that thread describes the duality (https://github.com/pkg/errors/issues/34#issuecomment-225921170). Also it seems topical because of the advice myself and others have given that (widely reused) libraries should avoid logging internally (as I wrote about here https://github.com/go-kit/kit/issues/42).

Chris

[kaveh.sh...@gmail.com]

(IMHO)

- I like the log package as it is, except for getting the default logger, would be nice if it was there.

- I like the colog package. It hijacks the standard log and also provide hooks; so you could target any destination.

- In my tweets I've made a mistake by mixing traces & logs. Yet again a structured log should use only Key-Value sets. Go is not as strict as say Java (throws notFound); we know nothing about the error we get from a function (& hell they are mostly pointers and I don't believe in recopies that are not part of language or it's standard libraries and starts with "you should..." - much). So log.Println(`error:`, err) is all what we have (in most cases) - the traces.

- For Go, not being that strict about what kind of errors gonna be there, bloated interfaces (& levels & structs) are mostly overkill - they should be piled upon the base & the base should be as simple as possible (but not simplere?).

- Are logs considered some kind of metrics too? If yes the structure should not be more complicated than a map. If no what is the difference? (I said logs should be local, metrics should not. Maybe I should say traces & "raw" logs should be local & "meaningful", actionable logs not).

- I like to see a difference between "What's the code doing?" and "What's the app doing?" somehow reflected in this logging thing (perhaps call them traces & metrics?)

Again "levels" & and "structured logging" are needed "when [...]" but not always. Anything else could be done in hooks.

[Aiden Scandella]

>>>
>>> --
>>> You received this message because you are subscribed to the Google Groups
>>> "golang-dev" group.
>>> To unsubscribe from this group and stop receiving emails from it, send an
>>> email to golang-dev+...@googlegroups.com.
>>> For more options, visit https://groups.google.com/d/optout.
>
> --
> You received this message because you are subscribed to the Google Groups "golang-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to golang-dev+...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[sha...@google.com]

I agree with Brian, that the greatest benefit to having a standard logging interface that 3rd party packages can implement is the ability for the application programmer to swap out loggers at will.

I am therefore going to focus on a standard interface here, and not implementation optimizations.

I have 2 things I’d like to propose for this standard interface. There are more things that need discussion of course (eg. structured logging), but these are just the 2 I feel strongly about.

#1 Leveling:

Most popular Go logging pkgs offer the ability for developers to log with levels (via instance of some logger, though this is less relevant to my point) ala:

var log MyFavoriteLogger
log.Error(“whoops!”)
log.Fatal(“aw, man :/”)

There is probably some common, minimal subset of these leveling methods that we could have in our standard interface which would work for many applications. Like Brian’s proposal here: https://github.com/bketelsen/logr/blob/master/logr.go:

or eg:

type Logger interface {
    Info(...interface{}) // or whatever args
    Error(...interface{})
    Fatal(...interface{})
    // … etc
}

But requiring any subset of these leveling methods to satisfy the standard logging interface will, I fear, be restrictive enough that either many logging packages won’t implement the interface, applications won’t pass around an instance of the interface, or both. This restrictive interface will a) require libs to implement *all* of these methods on their logger in order to satisfy the interface (will this make sense for all logging packages?), and b) restrict applications from *only* using this set of leveling methods if passing around our standard logging interface.

Finding a nice middle ground between these is going to be a pain, and I think that even if we did find something that was OK, I’m not sure we’d be able to convince folks to actually use the interface.

So my thought is, what if we declare a canonical (perhaps exhaustive) set of levels - constants - and have a much leaner interface, eg:

type Logger interface{
    Log(log.Level, ...interface{}) // or whatever as the args after level
    Logf(log.Level, string, ...interface{}) // ? maybe?
    // …. WithFields, etc whatever else
}

This would be fairly straightforward for logging library maintainers to implement, just need to map standard levels to the appropriate method in their pkg, eg:

func (l MyLogger) Log(level log.Level, args ...interface{}) {
    switch level {
    case log.Warn:
        l.Warn(args)
    case log.Error:
        l.Error(args)
    case log.Panic:
        l.Error(args) // maybe this library doesn’t believe in log.Panic, so map it to error
    // etc ….
    default:
        l.Print(args) // or whatever
    }
}

Thoughts?

#2 Set Out:
The second thing I’d like to propose adding to the interface is a common way to swap out the backend for a given logger, eg.:

type Logger interface{
    // ...
    WithOut(io.Writer) Logger
    // ...
}

Most logging packages that I have looked at (logurs, zap, seelog, log15) have a way of setting this by providing an io.Writer, just everyone has a different func signature for doing so.

LMK your feedback. Happy to provide more rationale or information.

[Bjørn Erik Pedersen]

Long and interesting thread, my 50 cents:

I agree there is a difference between Application logging and "other type of logging."

The number one gotcha I have had with application logging in the later years, was some disabled debug logging in a hot path. So, it was disabled, but the creation of the log message still allocated.

So any log API should take this into account.

Getting help from the compiler would be great, adding if `log.IsEnabled` around every log statement is less than optimal.

I thought something in the line of this, it looks ugly, but it may be made liveable, maybe:

```

type F func()

func (l LoggerF) Info(f F) {
	if l.Enabled {
		f()
	}
}

```

The disabled version is "free":

BenchmarkLog/LoggerI:_Disabled-4             2000000           569 ns/op        1008 B/op          9 allocs/op
BenchmarkLog/LoggerF:_Disabled-4            2000000000           0.00 ns/op        0 B/op          0 allocs/op
BenchmarkLog/LoggerI:_Enabled-4              2000000           752 ns/op        1008 B/op          9 allocs/op
BenchmarkLog/LoggerF:_Enabled-4              2000000           748 ns/op        1008 B/op          9 allocs/op

[Manlio Perillo]

Il giorno mercoledì 18 gennaio 2017 21:02:20 UTC+1, Dave Cheney ha scritto:

Hello,

By my informal survey, logging in Go applications follows three routes:

- Using some form of fmt.Printf
- Using functions from the log package
- Declaring a log variable at a package level

> [...]

 

I've tried to codify my solution to this problem with these recommendations.

- libraries should not log error messages, they should return error values

This is the pattern I'm using in a web application.

I use the log package to log *only* errors detected in the HTTP handlers.

 

- if libraries need to log _informational_ messages, they should do so
using a value passed in during construction, usually stored in their
structure. I believe this is what Brian refers to when he says "A
common log interface", the type of the logger stored in your type and
availble to methods to use to log informational mesages.

I'm experimenting with a different solution: I have an internal debug package.

This package, like the standard log package, has a global logger that can be configured.

So I have:

- log.Print when logging an error

- debug.Print when logging a debug message

There is one problem with this solution.

When both loggers use the same io.Writer, the output messages may end up interleaved.

Manlio

[Carl Johnson]

If we think of logs as being key/value pairs, what are the common keys? Message is one key, obviously. Another is date. Level is popular. Request ID, maybe. Having a log.Info vs. log.Error seems to me to just be a shortcut for demuxing the KV stream and only sending some requests to Stdout or some other io.Writer. Would it be possible to just make a standard set of keys or will we always need to be able to add arbitrary new ones?

[co...@lanou.com]

I would like to see us take the simplest interface definition possible.

Something like:

type Log interface {

 Print(v ...interface{})

}

This would allow for the following types of logging:

// common formatted string output

Print(fmt.Sprintf(“some custom print string: %s”, value))

// no format string, just values

Print(someText, struct1, struct2, err)

// Custom key value style structs that can be interrogated with the logger that satisfied the interface to create structured loggin

Print(keyValueStruct, keyValueStruct, keyValueStruct)

// log levels (with a clog style implementation)

Print(“info: starting up system”)

Print(fmt.Sprintf(“err: kaboom %s”, err))

I'm uncertain if this will allow us to properly use zero allocation loggers which has been a topic for discussion in this thread. Perhaps somebody has an answer to that with the provided interface proposal above.

Also, context has been discussed several times. I'm concerned that making that a part of the interface will reduce adoption as many times you don't need context for logging. I do understand the need, however, and perhaps that means two interfaces would be required. The one proposed above, and a second one:

type LogWithContext interface {

 Print(ctx context.Context, v ...interface{})

}

That brings in another dependency from the core library, but assuming you require it, you have already accepted that dependency.

[co...@lanou.com]

I had the wrong link for leveled logging in my example.  I meant colog. Sorry for the confusion.

[Andy Balholm]

No one will ever come up with a comprehensive list of log keys. For example, github.com/andybalholm/grayland uses some standard ones, like hostname and ip, some less common ones like from and to, and rarities that would never make it to a standard list of keys (at least not with the same meanings), such as “list” for what whitelist an IP address was found on, and “delay” for how long a message was delayed by greylisting.

Andy

[Chris Hines]

I agree with the idea of the simplest interface definition goal. That was the goal we had designing the go-kit log package. We ended up with the following.

// Logger is the fundamental interface for all log operations. Log creates a

// log event from keyvals, a variadic sequence of alternating keys and values.

// Implementations must be safe for concurrent use by multiple goroutines. In

// particular, any implementation of Logger that appends to keyvals or

// modifies any of its elements must make a copy first.

type Logger interface {

    Log(keyvals ...interface{}) error

}

The two obvious differences from what Cory suggests are the focus on structured logging via key/value pairs and the error return value. I am not sure we should try to accommodate both unstructured and structured logging with a single interface. I think it will cause confusion and inconsistency while also complicating implementations. It will also create extra noise and dependencies at the call-site for the structured use case in order to use the special keyValueStruct. As for the error return value, we've had a rousing debate about that over the last year that is worth a read https://github.com/go-kit/kit/issues/164.

Chris

[Ian Davis]

On Wed, 18 Jan 2017, at 11:04 AM, Peter Bourgon wrote:
>
> Here are the questions as I see them:
>
> 1) What would a "standardized" logging interface look like?
> 2) How would that interface interact with related concerns e.g.
> context, tracing, instrumentation?
>

I think perhaps this focusses on the wrong problem. For me the real
issue is one of dependency injection: how do I make a third party
package use my logger?

For this to be possible the third party package needs to expose the
logging interface is expects plus a way to configure the package with an
instance of that interface. Then clients of the package can adapt the
interface to their own logging system.

This is how it's done in some packages that I work with extensively. For
example NSQ defines a logger interface with an Output method which you
can pass to a consumer:
https://godoc.org/github.com/nsqio/go-nsq#Consumer.SetLogger

For packages that use the stdlib log package directly I usually call
log.SetOutput with a an adapter that redirects writes to my own logger.

Rather than just define a standard logging interface I think we need a
standard interface for configuring a logger on a type, e.g.:

type LogSetter interface {
SetLogger(Logger)
}

type Logger interface {
Printf(format string, v ...interface{})
Printf(v ...interface{})
}

[Peter Bourgon]

On Mon, Jan 23, 2017 at 5:33 PM, Ian Davis <m...@iandavis.com> wrote:
> On Wed, 18 Jan 2017, at 11:04 AM, Peter Bourgon wrote:
>>
>> Here are the questions as I see them:
>>
>> 1) What would a "standardized" logging interface look like?
>> 2) How would that interface interact with related concerns e.g.
>> context, tracing, instrumentation?
>>
>
> I think perhaps this focusses on the wrong problem. For me the real
> issue is one of dependency injection: how do I make a third party
> package use my logger?
>
> For this to be possible the third party package needs to expose the
> logging interface is expects plus a way to configure the package with an
> instance of that interface.

The *package* should not be configured with a logger. That implies
package global state. Each component exported by the package that
needs to log should take a logger in its constructor as an interface
dependency: either some minimal standard interface, or an interface
defined by the package.

Then, indeed, clients of the package can adapt their own loggers as necessary.

> Then clients of the package can adapt the
> interface to their own logging system.
>
> This is how it's done in some packages that I work with extensively. For
> example NSQ defines a logger interface with an Output method which you
> can pass to a consumer:
> https://godoc.org/github.com/nsqio/go-nsq#Consumer.SetLogger
>
> For packages that use the stdlib log package directly I usually call
> log.SetOutput with a an adapter that redirects writes to my own logger.
>
> Rather than just define a standard logging interface I think we need a
> standard interface for configuring a logger on a type, e.g.:
>
> type LogSetter interface {
> SetLogger(Logger)
> }
>
> type Logger interface {
> Printf(format string, v ...interface{})
> Printf(v ...interface{})
> }
>

[Ian Davis]

On Mon, 23 Jan 2017, at 04:51 PM, Peter Bourgon wrote:
> On Mon, Jan 23, 2017 at 5:33 PM, Ian Davis <m...@iandavis.com> wrote:
> > On Wed, 18 Jan 2017, at 11:04 AM, Peter Bourgon wrote:
> >>
> >> Here are the questions as I see them:
> >>
> >> 1) What would a "standardized" logging interface look like?
> >> 2) How would that interface interact with related concerns e.g.
> >> context, tracing, instrumentation?
> >>
> >
> > I think perhaps this focusses on the wrong problem. For me the real
> > issue is one of dependency injection: how do I make a third party
> > package use my logger?
> >
> > For this to be possible the third party package needs to expose the
> > logging interface is expects plus a way to configure the package with an
> > instance of that interface.
>
> The *package* should not be configured with a logger. That implies
> package global state. Each component exported by the package that
> needs to log should take a logger in its constructor as an interface
> dependency: either some minimal standard interface, or an interface
> defined by the package.
>
> Then, indeed, clients of the package can adapt their own loggers as
> necessary.

Yes that was just a slip, I meant "type" as in the NSQ example I gave.

[Dave Cheney]

To amplify what Peter said;

How does a type know where to write data too? By writing to the supplied writer.

type DataWriter struct {
w io.Writer
...
}

How does a type know where to log messages too? By logging to the
supplied logger

type Overcomplicated struct {
l logger
}

Where logger is an interface either declared locally or in another
package. Personally I lean towards declaring the logger interface in
the same package as the type that uses it, but I've seen arguments
that this should be something that the std lib provides.

It certainly _should_not_ be defined in a third party, because we're
back to the same problem of transitive dependencies on logging
implementations.

[Ian Davis]

On Mon, 23 Jan 2017, at 07:42 PM, Dave Cheney wrote:
> To amplify what Peter said;
>
> How does a type know where to write data too? By writing to the supplied
> writer.
>
> type DataWriter struct {
> w io.Writer
> ...
> }
>
> How does a type know where to log messages too? By logging to the
> supplied logger
>
> type Overcomplicated struct {
> l logger
> }
>
> Where logger is an interface either declared locally or in another
> package. Personally I lean towards declaring the logger interface in
> the same package as the type that uses it, but I've seen arguments
> that this should be something that the std lib provides.
>
> It certainly _should_not_ be defined in a third party, because we're
> back to the same problem of transitive dependencies on logging
> implementations.
>

Yes I agree, this is exactly what I suggested. In my example NSQ defines
the interface it needs to log with and a method to supply it with a
suitable instance.

This is why I think focussing on standardising a logging interface is
missing the main problem. Packages can already declare their logging
interface and clients can supply adapted types that conform to the
interface. The missing piece is a convention, or really just a best
practice, that encourages packages to operate in this way.

[Dave Cheney]

I couldn't agree more.

[co...@lanou.com]

We talked about a `best practice` early on when we discussed this.  I would love it to be as simple as just writing a blog post.  It seems very obvious to me after writing Go for this long, yet most of the popular libraries do not do this, which leads me to believe it isn't obvious?

I would happily consume a packages interface for a logger interface I didn't agree with, simply because I at least have some level of control now (if nothing else, I can shut it up).

So, the real question, how do we get the community to adopt a best practice?

[Chris Hines]

I also concur and would like to make two additional points.

1. The exposed interface doesn't have to be focused on logging. I would rather see them provide richer information that could be adapted for purposes of metrics or tracing as well. See for example https://golang.org/pkg/net/http/httptrace/ as an example.

2. Sometime after we settled on the Go-kit Logger interface I realized that it was immensely more useful as a convention because its signature only uses primitives and the built in type error. The result is that any package can copy the declaration locally without adding any external dependencies.

Chris

[cep...@gmail.com]

When something makes it into the standard library or the language, it becomes the defacto standard.  This becomes an issue when we later discover limitations.  This is probably a cautionary learning around adding things to the standard library or toolchain too quickly.

I feel a lot has already been written about logging in Go (including a few slides at the last Gophercon).  Rather than bless someone as the "right" person, it seems reasonable to aggregate these talks and perspectives somewhere for people to decide.

I somewhat echo what Dave said, but maybe a bit more extreme.  To answer your two questions:

1) There shouldn't be a defacto interface and we should encourage APIs to expose the callback mechanism that best suits them.

2) I could reasonably see context, tracing, and others extending their API or adding helpers to make interacting with third party libraries easier.

On Wednesday, January 18, 2017 at 3:04:38 AM UTC-8, Peter Bourgon wrote:

Brian Ketelsen made a Tweet recently

 https://twitter.com/bketelsen/status/820768241849077760

which spawned an interesting proto-discussion about logging, tracing,
error reporting, and metrics, with Sameer, Rakyll, Dave, and other
titans of industry. We quickly outgrew the limits of Twitter, so I've
started this thread to continue the conversation.

Here are the questions as I see them:

1) What would a "standardized" logging interface look like?
2) How would that interface interact with related concerns e.g.
context, tracing, instrumentation?

[Henrik Johansson]

The "packages declare a local interface" is conceptually very neat but can't it become very tedious? I would have to provide a logger for all of the dependencies which can quickly grow. 

The benefit of a standard interface is that a program wide selection can be configured once like for example db/sql does. 

--

[Dave Cheney]

> The benefit of a standard interface is that a program wide selection can be configured once like for example db/sql does. 

I think when you read "interface" as in Application Programming Interface.

What I'm talking about is "interfaces" as in type logger interface.

[Henrik Johansson]

Well maybe both. I am just a little bit concerned about having to do

foreach dep in deps:

   dep.SetLogger(createLoggerForDep(dep))

It might not be an issue, perhaps I misunderstood how this is supposed to work.