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.

[Dave Cheney]

Here's a piece of made up code to try to illustrate what I'm thinking
logging could look like

package main

import "github.com/pkg/log"
import "github.com/webz/audit"
import "github.com/gorilla/mux"

type RequestLogger struct {
log.Logger
next http.Handler
}

func (r *RequestLogger) ServeHTTP(w ResponseWriter, r *Request) {
next.ServeHTTP(w, r)
r.log.Infof("%d %s %s", w.StatusCode, r.URL, r.Protocol)
}

func main() {
auditlog := log.NewFileLogger("/var/log/audit.log")
requestlog := log.NewFileLogger("/var/log/www/access.log")

r := mux.NewRouter()
// setup routes

r = audit.NewMiddleware(r, auditlog)

r = &RequestLogger {
Logger: requestlog,
next: r,
}

http.ListenAndServe(":8080", r)
}

Specifically there is no looping over each dependency and initializing
them, because there is no package level global to initialize.

[Henrik Johansson]

Yes this is normally what I try to do but imho there seems to always be some dependency or dependency's dependency that logs differently or not at all.

Supplying loggers consistently and throughout the whole app seems to be very difficult even if the idea is as simple as this.

My example looked like it implied package level global loggers but it still applies to your example. The top level libraries needs to do the same for their deps so on and so forth. If they don't then I have to find a way to inject a logger which may not always be possible.

Wouldn't a common interface with a "register logging driver" a'la db/sql be better?

[Dave Cheney]

No, that would be the worst; a silent global dependency which if missing from the final program means it magically stops working. Just search any of the usual go support forums to find people who use database/SQL and are bemused why it says that no driver is registered.

[Henrik Johansson]

Ok I get that but shuffling around loggers seems messy. I would prefer not to have to pollute my data structures with such a cross cutting thing as loggers.

It is a little bit like the context package but that has more clear benefit such as when to cancel or when a timeout has been reached etc.

[Dave Cheney]

But that's the point. Pushing that concern into a package level variable creates a direct dependency on the logging implementation and we're back to exactly the situation that big go projects find themselves.

a. Projects have to manage multiple logging libraries
b. Projects that are limited to only use packages that favor their chosen logging library
c. Libraries that cannot use *any* logging libraries, including the standard library, because they don't want to get the decision wrong and cut themselves out of some or all of the marketplace.

[Henrik Johansson]

But these would all go away with a db/sql solution.
It would require a common interface in the same fashion as db/sql and it would allow for the end user to easily select the implementation to use.

Missing the registration can happen of course but rarely more than once.

[Dave Cheney]

A database/sql like registration pattern requires everyone to agree on a single point of registration, and you're back to the same situation, a compile time dependency on a concrete implementation. 

[Henrik Johansson]

But that's done once in the main application and the choice has to be made at some point anyway.

[Dave Cheney]

Correct, but the point is to remove the compile time dependency on a logging library until main is compiled. This might seem like spitting hairs, but if you are writing a library, or decomposing a big application, then being able to compile your package without having the source of any logging library in your GOPATH is critical for decoupled design.  

[Henrik Johansson]

But can't the tests use another logger? They can register a NoOp logger or a StdOut logger of any flavor or even a default supplied logger?

[Dave Cheney]

I don't understand the tangent this conversation just took. Who mentioned testing?

[Henrik Johansson]

But surely a library that uses database/sql compile without having a concrete implementation available.

That's what made me assume you meant testing rather than pure compilation.

There is no tangent as far as I am concerned I just want to make sure that the end user, who has little time configuring various logging facilities, gets as smooth an experience as possible.

[Peter Bourgon]

On Tue, Jan 24, 2017 at 11:47 AM, Henrik Johansson <dahan...@gmail.com> wrote:
> But surely a library that uses database/sql compile without having a
> concrete implementation available.
> That's what made me assume you meant testing rather than pure compilation.
>
> There is no tangent as far as I am concerned I just want to make sure that
> the end user, who has little time configuring various logging facilities,
> gets as smooth an experience as possible.

Loggers are not "cross-cutting concerns" whose initialization costs or
ceremonies we should attempt to sweep under the rug. They are
dependencies, same as any other. We should make every effort to lift
them, carefully, into the conscious attention of the end user by
having our component constructors take them explicitly — rather than
bowing to the false economy of "smooth experiences" and hiding them in
e.g. global registries.

[Henrik Johansson]

My point is that the act of logging is important and should be on top of peoples minds and considerations.

The configuration and bootstrapping of said loggers however is not and if possible I think it should be hidden as much as possibly.

Injecting a "logging driver" in an import (with some config in init or main) and have all logging in the application log consistently seems good.

You are still required to select between the Elasticseach logger or stdout logger or whatever else you might want with whatever costs and dependencies that the choice might entail.

I still think that having my algorithm specific structs all carry a logger is bad and piggybacking on some other structs logger violates at least some principle of sw dev.

I concede that there are possible instances where you may want to use different loggers in different places but then having an instance logger is still feasible.

This idea simply, imho, gives the vast majority of apps an easy and cheap way to configure loggers. I think the "global registries are bad" argument is a bit of a red herring in this case. Just because global state is generally considered bad (I agree with this) does not make all such state bad. Smooth experiences should not be discounted out of hand as bad, most developers days are filled with little things that take time from actual valuable work. It adds up. 

 

[Paul Borman]

I like the ideas Chris and Cory presented.

What I would like is to tease apart writing log messages (e.g., log.Infof("my log message"))  and how those log messages are written to the log.  I will call these log and log writer packages.

A log package should not be restricted in the API used by programmers.  Some log packages would provide concrete logging functions and others might provide indirection via some sort of interface (I think concrete would be the most useful and common).  The standard Go log package as well as log15 and go-kit/log style logging interfaces should all be able to coexist within a single program as long as they are all written to use the standard log writer package.

The standard log writer package would define the LogWriter interface and provide functionality like:

// SetWriter sets the standard log writer to w.  Only package main should call SetWriter.

func SetWriter(w LogWriter)

There should be a default LogWriter package (probably part of the standard log package) that writes logs more or less the way the current package does.  This can be overridden by package main to use whatever LogWriter that program would like to use.

The LogWriter interface should support the concept of logging levels.  It should also support logging a string as well as a well defined structured logging format (I am leaving the exact interface up for debate).

I think if this separation can be agreed on, library programmers would be able to use whatever log package they want (e.g., log.Print vs a severity based structured log).  Application writers would be able to choose the appropriate log writer.  The debate on the LogWriter interface would not have to concern itself with ease of use as it would almost never be used directly.

The functionality of log.V(2).Info should be in a log package, not necessarily in the log writer package.

    -Paul

    

>>>>>>>>>> >>>> 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.
>>>>>
>>>>> --
>>>>> 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.

--
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.

[Dave Cheney]

> way to configure loggers. I think the "global registries are bad" argument
> is a bit of a red herring in this case. Just because global state is
> generally considered bad (I agree with this) does not make all such state
> bad.

No, actually global registries are bad. Consider for example net/http,
which has a default global mux and some helpers that register entries
with it. This makes it possible to write other packages, namely
net/http/pprof which register with this global mux. Sounds great
right? Except that now every single tutorial that talks about using
net/http/pprof has to come with a giant flashing warning sign that
this handler will be accessible to the internet if you're using the
default http mux.

What sounded like a great convenience ended up making a feature
designed to make it easy for developers to add debugging endpoints to
their application dangerous to use _in_the_default_case.

And now many lines did it save in the end, for all this confusion? one.

No. Global registries are not the solution to logging, or any other problem.

[Henrik Johansson]

We just have to disagree but if you can make end usage as easy then I am all for it.

Propagating loggers manually everywhere seems horrible but perhaps I am exaggerating the issue.

[Chris Hines]

I am not sure I fully understand your idea. Can you provide more detail around how logging packages would interact with the standard log writer package?

Thanks,

Chris

>>>>>>>>>> >>>>> [2] https://godoc.org/github.com/go-kit/kit/log#Context<br class="m_13609667854213

[Paul Borman]

Okay, below is a very simple design (it is not complete, I have never compiled it, and is only here for demonstrative purposes).  The first package, log, is one of many interfaces to logging.  The second package, logger, defines the LogWriter interface (the real one would be more complete) and a mechanism to change where logging is sent.  Note that there is an obvious race between SetLogger and Write and there is a fundamental issue of what to do with log messages in init functions.

I would expect there to be a lively discussion on what a structured Write would look like for LogWriter interface.  I didn't bother to try and define one here.

The point is the logging package a programmer normally interfaces with can be whatever is convenient for that programmer.  The program, on the other hand, can select what package is going to be used to actually log the data, which may write to a text file, write to a binary structured file, log in memory, sends it to syslog, writes to a database, etc.

You can imagine an implementation of LogWriter that optionally adds a stack trace to every log message, for example.

    -Paul

package log

import "logger"

func Fatalf(format string, v ...interface{}) {

        logger.Write(logger.Fatal, fmt.Sprintf(format, v...))

}

func Infof(format string, v ...interface{}) {

        logger.Write(logger.Info, fmt.Sprintf(format, v...))

}

package logger

// a Level is the severity level of the log message.

type Level uint

// Standard severity levels.  Verbose logging at level N (e.g., V(2))

// uses the severity of Debug + N.

const (

        Panic   = Level(iota) // Panic after logging

        Fatal                 // Exit with non-zero status after logging

        Error                 // Non fatal errors

        Warning               // Important but not actual errors

        Info                  // Normal logging

        Debug                 // Debug logging

)

func (l Level) String() string {

        const levels = "PFEWI"

        if l < debug {

                return levels[l : l+1]

        }

        return fmt.Sprintf("V%d", l-Debug)

}

// A LogWriter is a type that writes log data to some destination.

type LogWriter interface {

        // Writer writes the provided string to the log and the provided level.

        Write(Level, string)

}

var logger LogWriter = &defaultLogger{w: os.Stderr}

// SetLogger causes l to be the default logger.

func SetLogger(l Logger) {

        logger = l

}

type defaultLogger struct {

        w io.Writer

}

func (d defaultLogger) Write(level Level, msg string) {

        var nl string

        if len(msg) == 0 || msg[len(msg)-1] != '\n' {

                nl = "\n"

        }

        fmt.Fprint(w, level.String()+time.Format("15:04:05.99")+": "+msg+nl)

}

// Write writes msg at the specified level to the default logger.

func Write(level Level, msg string) {

        // maybe some sort of locking

        logger.Write(level, msg)

        switch level {

        case Panic:

                panic(msg)

        case Fatal:

                os.Exit(1)

        }

}

// LogTo sets the default logger to log to w.

func LogTo(w io.Writer) {

        SetLogger(&defaultLogger{w:w})

}

--

[Dave Cheney]

I think your proposal still requires a compile time dependency between the code logging and your logging implementation.

Can you show a sample package main that demonstrates how someone could use this proposal?

To unsubscribe from this group and stop receiving emails from it, send an email to golang-dev+...@googlegroups.com.

[Paul Borman]

package main

import (

    "logger"

    "my/goodlogger"

    "foo"

)

func init() {

    logger.SetLogger(goodlogger.New("/tmp/foo"))

}

main() {

    foo.Function()

}

package foo

import "slog"

func Function() {

    f := &slog.Message{

        Package: "foo",

        Caller: "Function",

        Message: "a log message",

    }

    f.Emit()

}

// Package goodlogger provides a pretty good logging system that

// generates three log files, ERROR, INFO, and DEBUG.

package goodlogger

import (

    "logger"

    "os"

)

type myLogger struct {

    fd [3]*os.File

}

func New(path string) logger.LogWriter {

    var err error

    var l myLogger

    l.fd[0], err = os.Create(path + ".ERROR")

    if err != nil {

        panic(err)

    }

    l.fd[1], err = os.Create(path + ".INFO")

    if err != nil {

        panic(err)

    }

    l.fd[2], err = os.Create(path + ".DEBUG")

    if err != nil {

        panic(err)

    }

    return &l

}

func (l *myLogger) Write(level logger.Level, message string)

{

    msg = []byte(time.Format("15:04:05.999") + ": " + message + "\n")

    if msg[len(msg)-2] == '\n' {

        msg = msg[:len(msg)-1]

    }

    if l <= logger.Error {

        l.fd[0].Write(msg)

    }

    if l < logger.Debug {

        l.fd[1].Write(msg)

    }

    l.fd[2].Write(msg)

}

package slog

import "logger"

type Message {

    Package string

    Caller  string

    Message string

}

func (m *Message) Emit() {

    logger.Writer(logger.Info, fmt.Sprintf("%s.%s: %s", m.Package, m.Caller, m.Message))

}

So main imports goodlogger and calls logger.SetLogger.  The person who wrote package foo for some reason likes the slog API for writing log messages, and has never hear of goodlogger, but doesn't care as it uses logger.Write to send the log message.  Likewise, the person who wrote goodlogger has never heard of the slog package, but doesn't care because it implements logger.LogWriter. 

There is, as I said, a chicken and egg initialization problem, what to do with log messages that happen during init time (which will certainly happen prior to init calling SetLogger in its init function).  There are solutions to the problem, but that is a different discussion. 

    -Paul

To unsubscribe from this group and stop receiving emails from it, send an email to golang-dev+unsubscribe@googlegroups.com.

[Dave Cheney]

Thanks for clarifying. Isn't this what https://godoc.org/log#SetOutput does now?

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

[Paul Borman]

No as there is no way to replace the other aspects of the logging package, such as formatting, timestamping, and so on.  The only thing  you can do with SetOutput is give it a writer that you can read formatted log messages from and then try to process them some other way by scraping them.  That eliminates the ability to produce structured binary logs, support log levels, etc.  I am suggesting an interface that provides more information.  Note that my example did not include structured logging, which would be required in a real solution, as I felt putting out a strawman for structured logging would detract from the concept of splitting what programs write from how logs are formatted and written.

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

[Edward Muller]

Loggers should be injected into dependencies. Full stop.

But if those dependencies define their own logging interfaces, then I'm worried that library developers will each define their own logging interface. The developer that wants levels will define an interface with levels, others will just define it as "Log(kv ...interface{})" or
"Print(v ...interface{})" and/or "Printf(f string, v ...interface{})". As soon as you have more than one logging interface to deal with you'll be ready to start flipping tables. Maybe that's a good thing to help the community flesh things out, but it's also chaotic and messy. And those interfaces will live on much longer than any of us would care for them to.

So what about passing in the io.Writer that a library could pass to whichever logger it wants? Maybe, but then we have the situation where libA will want to use structured logging in logfmt format, libB will do it with new line limited json output, libC (used by libB, not your application directly) will pretty print json and libD will do something else entirely making your log stream unusable. FWIW, I believe this is also a problem with Cory's suggestion above.

Something could be written that implements an io.Writer that tries to detect and handle all of those cases, normalizing whatever is possible to your preferred format, but that way lies some form of madness.

My suggestion is that a structured logging interface like the one in go-kit (https://github.com/go-kit/kit/tree/master/log) be included in the stdlib. Data logged via this interface could be adapted to any sort of output (line based messages, leveled logging, json structure, logfmt structure, etc) by the main program constructing the logger. The go-kit package already has formatters for logfmt and JSON. Adding additional formatters/filters (aka leveled logging)/etc could exist either in the stdlib or elsewhere as needed.

That doesn't address "zero allocation" loggers, but I'm not sure the added complexity they would require are worth it in the general case.

Nor does this address tracing/diagnostics/metrics (beyond logging different points of execution in a function/method and key/value pairs for later extraction) and the like, but I believe those are related, but orthogonal concerns.

Anyway, my 2 c.

>>>> 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.

[co...@lanou.com]

Edward,

I think what you said makes a lot of sense.  Choose an interface that can be adapted downwards if needed.  Such that any input you pass in can easily be consumed as structured, leveled, etc.

The difference between my proposal and go-kit was theirs returns an error (which I'm unsure should be a requirement, but I could be persuaded through some additional context perhaps?).

My proposal:

type Log interface {

 Print(v ...interface{})

}

Their implementation is :

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

I also agree that zero allocation loggers are out of scope here.  If zero allocations are that important to the log in a third party library that will have to be handled as a special case imo.

In general, our goal is to avoid flipping tables, that's for sure.

[Edward Muller]

An error should probably be returned, giving users the ability to choose to ignore them or not, cf. most of the fmt package's functions return arguments, which are almost always ignored, except when it's important that they aren't.

The other difference that I saw between the two is that your examples implied having the caller determine structure vs. the provider. Maybe that wasn't your intention and I misunderstood thought? If I am right It's a subtle, but IMO important difference. Maybe there are some assertions a formatter could do along the lines of Stringer that could become common though.

I also don't think context.Context should be involved here aside from maybe being used by the implementation for things like timeouts, cancelation and the like. Maybe there is a place for that as a logging user, but I'm not convinced atm.

I do think that go-kit's log.Context (https://godoc.org/github.com/go-kit/kit/log#Context) handles most needs (the one's I've seen anyway, so probably not complete) wrt injecting additional information that is transparently provided to down stream Log() calls.

--

[Chris Hines]

Cory,

In case you missed the link I provided earlier in this thread, there has been quite a lot written about the choice (or not) for the Log method to return an error in Go-kit issue #164.

I would also like to point out that on the performance front the most costly aspect of logging (outside of i/o costs) is typically the formatting of the output []byte. Passing raw values to the Log method has the benefit of deferring the formatting step or possibly avoiding it entirely if the log event gets filtered by the implementation. Of course skipping the call to Log entirely is even better, but difficult to do without being more invasive to the application code.

Chris

[sha...@google.com]

I think we need to reduce the scope of and simplify the problem statement.

IMO there are two major problems which should be solved by this logger interface.

1. eliminate the need for multiple logging-backend dependencies compiled in an application binary -- we need backend-agnostic logging libraries.

2. leveling. We need the ability to pass a level to a backend, as different backends will handle these levels differently. Eg. Google Cloud logging supports filtering on the front-end based on the level passed when the entry was written.

I leave out structured logging, as the k/v pairs end up as part of the entry payload / text. The formatted string can be constructed however the logging library chooses.

Now, I think we should defer solving the second problem (leveling), as the first is more pressing and will require less work on the part of authors of existing 3rd party logging packages. Let’s start with something small, let that gain traction, then move on to harder problems. (leveling will require us to come up with a standard set of levels which logging packages must use, as well as a standard way to pass these levels to a backend).

The first problem can be solved simply, though it will require rewrite work for 3rd party logging package authors. Not a terribly complicated rewrite, though.

My example impl:

// package log/logger (TBD, but for example’s sake)
// standard logging interface
type Log interface {
 Print(msg string) // note: concrete type
}

// GCP logger backend implementation (for example)
// package cloud.google.com/go/logging
type Logger struct {
 // … conn, etc.
}

func (l *Logger) Print(msg string) { // std interface impl
 l.Log(logging.Entry{Payload: msg}) // GCP-specific write, writes to buffer, periodically flushed
}

// package github.com/me/mylogger (my favorite logger, eg. logrus, log15)
type Logger struct {
 l logger.Log // std interface above
}

// SetLog sets a backend implementation of logger.Log
func (l *Logger) SetLog(ll logger.Log /* std interface */) {
 l.l = ll
}

// add all my favorite logging methods
func (l *Logger) Error(msg string) {
 // note: for this idea to work, all 3rd party logging packages like this one will need
 // to be reimplemented to write using the interface, not any concrete type
 l.l.Print("ERROR: " + msg)
}
// ... Warn, Debug, WithFields, etc

// my program
func main() {
 log := mylogger.New(gcplog.New())
 log.Error("whoops!") // goes to GCP, using mylogger’s entry payload formatting
}

[co...@lanou.com]

A group of us spent some time today cleaning up the Proposal Doc (thanks everyone!). 

We are looking for design suggestions from everyone to add to the document for review.  Proposals are due 2017-02-24.

Thanks again to everyone who is participating on this topic.  We look forward to your proposals!

Summary of todays meeting:

- Resolved all outstanding comments

- Revised Background

- Added Goals and Non-Goals section

- Updated Implementation

- Updated all other headings as TBD and will be updated as we review proposals.

[Dave Cheney]

Hello,

Can I ask what happened to this proposal? It started out several weeks
ago with a clear goal from Cory and Brian Ketelsen that you wanted to
see a Logger (name is not important) interface added to the standard
log package.

From this goal, with a well defined deliverable, the proposal has
mutated into an insipid call goal of

"As an Go application author, I want to be able to control the
(diagnostic) logging backend a library uses for the benefit of
avoiding missing log messages and keeping a consistent log entry
structure.

As a Go library author, I want to be able to log diagnostic
information for the benefit of making problems in my library easier to
diagnose."

Which I argue is already satisfied today by the stblib log package and
dozens of third party log implementations.

What happened to the clear, measurable goal of this proposal?

Tanks

Dave

[co...@lanou.com]

I think we can do a better job of detailing the goal. I think we might of lost some detail.  We'll work on that.

However, what was there (pasted in below), while it has great content, is not in itself an actual goal.  The plan was (and this is also in the document) to link to your recent article that describes in depth this problem.

So, other than the goal statement needing some work, does this satisfy in part your request to have this added back to the document?

Previous Goal Statement:

Currently logging in Go applications is handled in four ways

1. Using some form of fmt.Printf

2. Using functions from the log package

3. Declaring a log variable at a package level

4. Passing in a log object to a library (concrete or interface)

The first is out of scope for this proposal.

Despite the success of 12 factor, the second method, the log package in the standard library is considered inadequate for developer's needs. This view has been cemented by proposals to add so called leveled logging to the standard library package being declined such as https://github.com/golang/go/issues/2236.

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 three 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. This leads to projects composed of packages using multiple logging libraries, or fiefdoms of projects who can only consume packages that use the particular logging library.

3. mylogger.GetLogger implies global mutable state.

While this is excellent information, it's not directly a "Goal".  

[Dave Cheney]

Isn't the goal "to add a logger interface to the std lib log package"?

[sha...@google.com]

I think the goal needs to identify the problem that the interface would solve. I would argue that "add a logger interface" is actually less measurable - how do we know if the new interface added any value for the go developer? I think we need a concrete, written understanding of what value the interface would add before we can move forward with implementation.

Do you disagree that the standard logger would solve the problem stated? Does it need to be augmented or changed? Reworded?

Or do you disagree with the need to identify the problem(s) in this way?

Thanks for your insight.

Sarah

[Sameer Ajmani]

One goal I have for any standard logging interface (and also interfaces for tracing, error reporting, and metrics) is that they are platform-agnostic. The particular use case I have in mind is enabling application developers and, especially, library developers to do logging (and tracing, error reporting, etc) without knowing or caring about the specific implementation that's linked into the program. From a business standpoint, I want to enable Go programs written to run on private machines or one Cloud platform to be easy to migrate to other platforms.

This has little to do with the design of the API, of course, but it's at least a concrete and testable goal for any solution.

Goals for the API might include:
- support for passing key-value pairs to the implementation
- support for passing Context to the implementation
- support for printf-style formatting
- support for low-allocation logging (like Uber zap)

Additional question: are logging and tracing essentially the same API? That is, is tracing essentially "logging to a request context"?

S

[Dave Cheney]

Hi Sarah,

This discussion started with a call to action by Brian,
https://twitter.com/bketelsen/status/820768241849077760, for a logging
interface that all Go developers could use.

There was a long conversation over twitter, slack, and this thread
about what that actually means; because for me initially it didn't
mean anything -- how would having an interface to a type in a package
that nobody (if they did we wouldn't have this problem) uses solve the
complaints that the respondents to Brian's tweet had.

From those discussions two ideas emerged

1. an interface, rather than a concrete type, is crucial for breaking
the compile time dependency on a specific logging implementation.
2. if there is to be an interface declaration, where should it be
defined; which package, who owns it, etc.

From this debate the document linked above was written up, and bares
the title "Proposal: Add Logging interface to standard library" which
several of us collaborated on in slack until the document was made
public this morning.

For me, the purpose of the document is clear: add a logging interface
to the standard library. My concern is the rest of the document _used_
to contain a discussion of how the two ideas "use an interface, not a
concrete type", and "who should own this interface" but were recently
removed from the document and it feels like everything has reverted to
square one.

Is the goal of this proposal no longer to add an interface type to the
standard library for the purpose of decoupling logger implementations
from their users?

Thanks

Dave

[Sarah Adams]

Hm, yea I remember Brian's tweet. I looked at his prototype / documentation here too (https://github.com/bketelsen/logr). 

I think something along those lines is still the vague goal. Though, I think the level of full-featuredness is still very TBD.

I also think that your first goal statement, "an interface, rather than a concrete type, is crucial for breaking the compile time dependency on a specific logging implementation." is also still the goal. With this new problem statement, we were trying to outline the benefits of removing the compile time dependency, other than just "too many logging packages in my binary". Perhaps we did a poor job of this, or didn't capture enough of the benefits. Maybe adding this statement back in as a prefix to our problem statement would help with clarity. I'll add this as a suggestion on the doc.

As for, "if there is to be an interface declaration, where should it be defined; which package, who owns it, etc.", we cleaned this discussion up and replaced it with a concrete proposal for a solution - pkg should live in golang.org/x/exp for a while, then ideally move to std lib. If we can't get it into std lib, we can figure out where else to put it when the time comes. This note is under the "Implementation" header.

Perhaps we should leave the discussion points around this as rationale for this conclusion. Again, I'll add a note on the doc.

Our goal today was to clean up the document, as there were many divergent opinions and comments, making the doc hard to read. Our intention was not to remove crucial bits of information. We may have messed up a bit here. Please continue to point us at bits that we took off which should be added back. 

We're definitely trying to move this forward, not backward. Cleaning up the doc seemed the first step forward.

Thanks, Dave.

Sarah

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

I do like a simple interface. I just want it to deliver a log message to whatever underlying logger is consuming it. It would be annoying to see the implementation details of a specific logger, pollutes a code base in all places.

Providing rich messages, would be a matter of the target logger capabilities. If the logger is providing some fat facts about some specific aspects of the app, going inside say influxdb or promptheos, it should do it using just what info the app provides - prefixes, constants, etc, etc.

And having a - ehem - global logger (as it is) is nice in that I can see what is some package doing inside my own logs (and do something about it, parsing it, transforming it and the like); and we should be able to change it.

[Henrik Johansson]

I have turned on the central logger idea and passing a logger around or as member variable is fine for me. 

The more pressing issue is that of the interface and levels. What seems to be the consensus so far? I personally like levels but there are generally too many for practical use. 

--

[Jaana Burcu Dogan]

+rogpeppe

On Monday, February 6, 2017 at 5:22:35 PM UTC-8, Sameer Ajmani wrote:

One goal I have for any standard logging interface (and also interfaces for tracing, error reporting, and metrics) is that they are platform-agnostic. The particular use case I have in mind is enabling application developers and, especially, library developers to do logging (and tracing, error reporting, etc) without knowing or caring about the specific implementation that's linked into the program. From a business standpoint, I want to enable Go programs written to run on private machines or one Cloud platform to be easy to migrate to other platforms.

This has little to do with the design of the API, of course, but it's at least a concrete and testable goal for any solution.

Goals for the API might include:
- support for passing key-value pairs to the implementation
- support for passing Context to the implementation
- support for printf-style formatting
- support for low-allocation logging (like Uber zap)

I think the doc will have an appendix discussing the case for these goals. It seems like the current state thinks these are non-goals.

I would suggest us to not finalize anything before we sort all issues on my initial email on this thread and add why there are not non-goals if the solution won't include immediate improvements for these cases. These notes are repeated feedback from a variety of companies over the course of years, not from a single point of discussion or a rage ;)

 

Additional question: are logging and tracing essentially the same API? That is, is tracing essentially "logging to a request context"?

Or could trace ID would be a argument in Logger.Print? This is what Roger Peppe was suggesting during the first round of common tracing APIs for Go.

[Ross Light]

Hello all,

I have written a concrete proposal with detailed rationale.  My design is here, and I've also linked to it from the main proposal document.  There's already some good feedback going, please read and leave comments.

Cory, Sarah, and I would like to see other concrete design proposals as well.  If you would like to propose alternate designs, please add a link to your doc to the main proposal document before 2017-03-03.

Thank you, and looking forward to seeing proposals!

-Ross

--
You received this message because you are subscribed to a topic in the Google Groups "golang-dev" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-dev/F3l9Iz1JX4g/unsubscribe.
To unsubscribe from this group and all its topics, send an email to golang-dev+...@googlegroups.com.

[Manlio Perillo]

On Tue, Feb 21, 2017 at 10:21 PM, 'Ross Light' via golang-dev
<golan...@googlegroups.com> wrote:
> Hello all,
>
> I have written a concrete proposal with detailed rationale. My design is
> here, and I've also linked to it from the main proposal document. There's
> already some good feedback going, please read and leave comments.
>
> Cory, Sarah, and I would like to see other concrete design proposals as
> well. If you would like to propose alternate designs, please add a link to
> your doc to the main proposal document before 2017-03-03.
>
> Thank you, and looking forward to seeing proposals!
> -Ross
>

I don't understand the definition of log levels.
I use the log package for only one reason: log errors that I have handled.
As an example an HTTP handler function, in case of error, returns
http.StatusInternalServerError to the client and log the error message
to a file.

In the design proposal now we have Debug and Info levels, however none of these
match with my current usage.

One other issue, IMHO, is that if you want to report messages to the
user, you should use
a different package, e.g. messages. AFAIK messages to users are not
to be logged, but are
meant to be interactive messages, e.g. messages printed on stderr when
an interactive program
is running. Using a different package you can optimize messages
delivering on a terminal, e.g. using colors.

The same with debug messages: you should use a different package.
Again, using a different package
you can optimize debug information, e.g. adding detail levels.

What I would like to have in the standard library is a Writer that
allow concurrent calls to the Write method,
without interleaving the output, so that the log, messages and debug
package can safely write to the same file
(but probably this is already the case).

> [...]

Thanks
Manlio

[Paul Borman]

Debug logs are used for development and may significantly slow down the process (they should be off by default).  Regular log messages normally should be logged to some (semi)permanent storage that can be looked at to see how a program is doing or why it failed.  I honestly prefer to have a critical level as well that flushes and buffers any log messages and perhaps gets other special treatment.  In general, I find debug, info, and error as the three important levels.  I think it is a mistake to not define something more critical than info.  People are going to define levels, but they may be different between different frontends and multiple frontend may be writing to the same backend logging package.  Best to at least have the three.

[Lucio De Re]

On 2/22/17, Manlio Perillo <manlio....@gmail.com> wrote:
> [ ... ]

>
> In the design proposal now we have Debug and Info levels, however none of
> these
> match with my current usage.
>

Manlio, think of it as if one were to add stdlog, stdinfo, stddbg,
possibly others, to the conventional list of useful output files from
a program.

Stderr came from just such a thought and everything since has been
subsumed into "log" unless, as you suggest, it needed interaction.

Your use case is individual and does not scale to the needs of a
community. At the other extreme, I'd prefer the receiver in ALL
logging invocation to be the target output, but with powerful
redirection behind the scenes.

As I'm not sufficiently academic, I'd rather leave the details to
those who are. A single, powerful, but not intrusive logging system
that can be conveniently redirected (that single ">" symbol on the
command line was a stroke of genius - even if IBM JCL had a more
powerful, less readable version long before the Bourne shell),
filtered and, critically, turned off at minimal computing cost, is my
idea of logging heaven.

Lucio.

[Lucio De Re]

PS: Stdinfo and Stdstat come to mind as further log levels represented
as output files. Of course, the names may well be Log*, in a brave new
logging world of remote network (read "web") services that need
careful nurturing to stay competitive.

Lucio.

--
Lucio De Re
2 Piet Retief St
Kestell (Eastern Free State)
9860 South Africa

Ph.: +27 58 653 1433
Cell: +27 83 251 5824
FAX: +27 58 653 1435

[will....@bigcommerce.com]

I guess I'm late to this party. Just heard about this thread.

I think go-kit's logger has it almost right:

    type Logger interface {

        Log(keyvals ...interface{}) error

    }

The interface is simple and expressive. Log levels can be represented as just another key-value pair. Extra logger functionality can reside in separate functions and decorators to keep the interface small (see go-kit's log.Context). If you wish, you could specify that a single argument defaults to the key "message" or something to be compatible with non-structured logging use.

For application logging, which is what the standard library log package addresses, the only thing I would change is the error result: it should be removed, like the standard library log package. So:

    type Logger interface {

        Log(keyvals ...interface{})

    }

"Event" logging (cf. application logging) is something the go-kit log package attempts to do as well, which is why it returns an error. Application loggers shouldn't return errors because it's unreasonable for callers to handle them (it's an interface, after all, and logger impls can (should!) come from anywhere, in general). My part in the discussion that Chris Hines linked to, where we and Peter Bourgon dig into this, starts here: https://github.com/go-kit/kit/issues/164#issuecomment-273658327. It seems to me that if you need to shoehorn event logging into application logging, you can handle the error in your logger impl. I don't see any value in application loggers propagating log errors up the logger decorator chain.

It seems to me if you're interested in tracking metrics or whatever, you can log that data as keys and values. Why special case it?

Example for a leveled logger off the top of my head using the modified Logger above:

    type Logger interface {

        Log(keyvals ...interface{})

    }

    type Context struct {

        keyvals []interface{}

        logger Logger

    }

    func (c *Context) Log(keyvals ...interface{}) {

        c.logger.Log(append(c.keyvals, keyvals...)

    }

    type LevelLogger interface {

        Logger

        Debug(keyvals ...interface{})

        Info(keyvals ...interface{})

        Error(keyvals ...interface{})

        Warning(keyvals ...interface{})

        Critical(keyvals ...interface{})

    }

    type loggerDebug struct { Logger }

    type loggerInfo struct { Logger }

    type loggerError struct { Logger }

    type loggerWarning struct { Logger }

    type loggerCritical struct { Logger }

    func (l loggerDebug) Debug(keyvals ...interface{}) { NewContext(l.Logger, "level", "debug").Log(keyvals...) }

    func (l loggerInfo) Info(keyvals ...interface{}) { NewContext(l.Logger, "level", "info").Log(keyvals...) }

    func (l loggerError) Error(keyvals ...interface{}) { NewContext(l.Logger, "level", "error").Log(keyvals...) }

    func (l loggerWarning) Warning(keyvals ...interface{}) { NewContext(l.Logger, "level", "warning").Log(keyvals...) }

    func (l loggerCritical) Critical(keyvals ...interface{}) { NewContext(l.Logger, "level", "critical").Log(keyvals...) }

    type dropLoggerDebug struct{}

    type dropLoggerInfo struct{}

    type dropLoggerError struct{}

    type dropLoggerWarning struct{}

    type dropLoggerCritical struct{}

    func (dropLoggerDebug) Debug(keyvals ...interface{}) {}

    func (dropLoggerInfo) Info(keyvals ...interface{}) {}

    func (dropLoggerError) Error(keyvals ...interface{}) {}

    func (dropLoggerWarning) Warning(keyvals ...interface{}) {}

    func (dropLoggerCritical) Critical(keyvals ...interface{}) {}

    type DebugLogger struct {

        Logger

        loggerDebug

        loggerInfo

        loggerError

        loggerWarning

        loggerCritical

    }

    type InfoLogger struct {

        Logger

        dropLoggerDebug

        loggerInfo

        loggerError

        loggerWarning

        loggerCritical

    }

    type ErrorLogger struct {

        Logger

        dropLoggerDebug

        dropLoggerInfo

        loggerError

        loggerWarning

        loggerCritical

    }

    type WarningLogger struct {

        Logger

        dropLoggerDebug

        dropLoggerInfo

        dropLoggerError

        loggerWarning

        loggerCritical

    }

    type CriticalLogger struct {

        Logger

        dropLoggerDebug

        dropLoggerInfo

        dropLoggerError

        dropLoggerWarning

        loggerCritical

    }

[3] https://godoc.org/github.com/go-kit/kit/log/experimental_level

[Peter Bourgon]

Chris and I have completed our proposal for a standard logger
interface, based on the Go kit logger. You can find and comment on it
via the link below.

https://docs.google.com/document/d/1shW9DZJXOeGbG9Mr9Us9MiaPqmlcVatD_D8lrOXRNMU/edit

Cheers,
Peter.

[saif]

Can you prioritize:

1) contextual logging

2) standard interface for loggers

You can  ignore leveled logs for now, because for leveled logs application can have various levels for their logs.
As an alternative for leveled logs, one can just do:

import (

    "strings"

)

// LogFunc is a standard interface

type LogLevel int

func (this *LogLevel) WrapFunc(level int, fn LogFunc, prefix string) LogFunc {

    prefix = strings.Replace(prefix, "%", "", -1)

    return func(s string, as ...interface{}) {

        if level <= int(*this) {

            fn(prefix+s, as...)

        }

    }

}

func (this *LogLevel) SetLevel(n int) {
    *this = (LogLevel)(n)
}

In addition please add a PrintStacktrace() for LogFunc:

func (this LogFunc) PrintStackTrace(n int) {
    this("%s", _stackTrace(n, 4))
}

Example implementation:

github.com/noypi/logfn

Thanks,

s

[adrian....@gmail.com]

(... previous post was broken...)

In addition please add a PrintStacktrace() for LogFunc:

Example: https://github.com/noypi/logfn

<span style="color: #0

[Sarah Adams]

We (Ross Light, Herbie Ong and myself), responsible for this proposal for a standard logger interface, have decided to drop the proposal. The proposal aimed to reduce the number of Go libraries1 importing concrete loggers. The solution was to introduce a standard interface which library authors could log to instead, allowing the application author to plumb down their preferred concrete logger implementation.

We have not found enough Go libraries which import and use a concrete logger to justify continued work on this proposal.

Thank you to all of you who helped us create this proposal. We have learned much about community needs for logging, logger APIs and implementations during this process.

Should anyone have a different take on the need for a standard logging interface, we encourage you to please continue this discussion and submit your own proposals.

- Go on Cloud team at Google

1 packages intended to be imported by another package

[Chris Hines]

In addition to the proposal document we wrote, here are slides from a talk I gave about our design at the Captial Go conference April 25.

https://speakerdeck.com/chrishines/go-kit-log-package

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.

Chris

[jorda...@gmail.com]

I know this thread is old... But for people that are looking for some simple logging by level functionality I have added basic logging levels to the default Go log package.  You can find my changes here:

https://github.com/gologme/log

In addition to adding Info, Warn, and Debug, users can also define their own arbitrary logging levels.  Also, logging levels are enabled or disabled individually.   So you can enable just Debug logs without getting Info and Warn.  The enabling only impacts the new added logging levels, not the traditional Print and Fatal loggers. 

All of the original functionality still exists and is unchanged. Though, I did enable the ability for users to define the calldepth. 

Bret