Proposal: Go 2: Create logger interface in the standard log package, with additional levels. Optionally add it to context package, too

[EVODelavega]

Logging is important, I think we can all agree that it is. The standard "log" package simply is too limited as it stands, so it's extremely common to use a third party package (logrus, zerolog, etc...). These third party packages don't necessarily share the same interface. It would be great to have a usable logger in the standard lib, and an interface so the community can adopt a standard approach to logging.

So what is the current logger missing?

Currently, only focusing on the output functions, we have 3 to choose from:

• Print & co (Println, Printf)
• Fatal & co (Fatalln, Fatalf) - equivalent to the Print equivalent + os.Exit(1)
• Panic & co (Panicln, Panicf) - equivalent to Print equivalent + panic()

Naturally, the latter is not commonly used if you want to honour the go proverbs.

The most obvious reason for people to use a third party logger is to be able to differentiate the log output, using the standard levels. To this end, Print & co are effectively replaced with:

• Debug & co
• Info & co
• Warn & co
• Error & co

There are 2 more (fairly) common log levels that will be discussed separately further down: Trace and Custom.

Contextual fields/values (prefix &co)

Something that is commonly done, too, is adding trace id's or correlation id's in logger output. With the standard package, it's possible to write something like this:

    l := log.NewLogger(
       os.Stdout,
       fmt.Sprintf("trace ID: %v", ctx.Value(traceIDKey)),
       log.Ldate | log.Ltime | log.Lshortfile,
    )

Third party packages allow you to add any number of prefixes/fields to individual messages, by doing things like:

    zerologger.Debug().Str("trace ID", traceIDValue).Msg("this is the message")
    logrus.WithField("trace ID", traceIDValue).Debug("this is the message")

Should I want to do the same thing with the standard logger, I need to make sure the particular logger isn't used concurrently. Sure, the logger guarantees the writer is accessed sequentially, but I'm forced to write this:

    oldPrefix := stdLogger.Prefix()
    stdLogger.SetPrefix(fmt.Sprintf("%s - trace ID: %s", oldPrefix traceID)) // sets the prefix
    stdLogger.Println("this is the message")
    stdLogger.SetPrefix(oldPrefix)

Clearly, though the writer is accessed sequentially, it's not hard to imagine that there could be a second routine either calling Print after you've set the prefix, or conversely: it's equally possible that the prefix you've just set is overwritten by another routine between your setting a prefix, and actually logging the output. This is a big problem that needs to be address should we want the standard log package to be usable in real life.

What about context.Context?

That brings me to something I'd personally consider to be a nice addition to the log package in general. Those trace ID's are very commonly used, and very useful. Quite often people end up writing their own packages, or handlers to automatically get the trace ID's from request headers (or generate them, or wherever), and add them to the context. It would be nice to be able to add this to the logger API:

type Logger Interface {
    Debug(string) // all the log levels etc...
    SetCtxCallback(func(context.Context, Logger) context.Context) /// add this
    Ctx(context.Context) (Logger, context.Context) // add this
}

With these additional functions, I'd be able to create a logger and do something like this:

    logger.SetCtxCallback(func (ctx context.Context, logger log.Logger) context.Context {
        tID := ctx.Value(traceIDKey)
        if traceID, ok := tID.(string); ok {
            logger.SetPrefix(fmt.Sprintf("trace ID: ", traceID))
            return ctx// done, added the prefix
        }
        // generate new traceID
        logger.SetPrefix(fmt.Sprintf("trace ID: ", traceID))
        return context.WithValue(ctx, traceIDKey, traceID) // return context with value
    })

// use like this:

logger, ctx = logger.Ctx(ctx)
logger.Infof("There is a prefix with the trace ID %v", ctx.Value(traceIDKey))

Something that might be worth discussing is that, given the logger can be made context aware now, whether or not the log levels could be ramped up should the context be cancelled by the time the writer is reached. Maybe that could be configured. This probably doesn't add much value, and is a bit silly, but just thought I'd mention it.

Trace, custom levels, and the Print & co calls

The trace log level is debatable. There already is a Log function in the runtime/trace package, and I'd argue it's better to keep it there. The Trace(f|ln) functions can simply be omitted from the logger interface.

Personally, I'm not sure if I've ever felt the need to have a custom log level. It's possible that there might be a genuine need to support this, perhaps not. Should this be added, I think the best approach to use is to implement a Custom & co function that takes 1 additional argument allowing to specify the desired level:

logger.Custom("my-level", "this is the message")

My idea for the Printcalls is to have them dynamically log at the minimum log level that is enabled. During development (or whenever the log level is set to debug, Print will be equivalent to Debug, if the level is set to warn, then Print is equivalent to Warn etc... This is not to encourage abuse, but more to make the transition to the standard package easier. Of course, the Print calls should not ramp up to Fatal if the configured log level is Fatal. Arguably, it shouldn't go higher than Warn.

Specific changes to the log package

TL;DR, here's what this proposal boils down to:

Change the log.Logger type to an interface

Having a common denominator logger interface in the standard package would make life a lot easier, and could go a long way WRT encouraging drop-in replacement packages for logging, or at the very least: uniformity. The interface I have in mind is this:

type Logger interface {
    // all levels + Prin
    Print(v ...interface{})
    Printf(format string, v ...interface{})
    Println(v ...interface{})
    Debug(v ...interface{})
    Debugf(format string, v ...interface{})
    Debugln(v ...interface{})
    Info(v ...interface{})
    Infof(format string, v ...interface{})
    Infoln(v ...interface{})
    Warn(v ...interface{})
    Warnf(format string, v ...interface{})
    Warnln(v ...interface{})
    Error(v ...interface{})
    Errorf(format string, v ...interface{})
    Errorln(v ...interface{})
    Fatal(v ...interface{})
    Fatalf(format string, v ...interface{})
    Fatalln(v ...interface{})
    Panic(v ...interface{})
    Panicf(format string, v ...interface{})
    Panicln(v ...interface{})

    // Prefix - chainable so it can create a logger instance, safe for concurrent use
    Prefix(prefix string) Logger
    // Prefixf to avoid having to use fmt.Sprintf whenever using this
    Prefixf(fromat string, v ...interface{}) Logger
    // fields for other formatters, acts like prefix be default
    WithField(k, v interface{}) Logger

    // Context stuff as explained earlier
    Ctx(ctx context.Context) (Logger, context.Context)
    SetCtxCallback(func(ctx context.Context, logger Logger) context.Context)
}

Closing thoughts

I'm aware that there are a couple of things about this proposal that are perhaps too broad. I'm looking forward to your feedback, comments, ideas, etc... I honestly believe the log package needs to be a bit more flexible, and I think this is a good way of going about it. Then again, that's one persons idea/opinion

[ianlancetaylor]

Similar to #13182. That may be a better place to discuss this.

[EVODelavega]

@ianlancetaylor Damn, I looked through some issues to see if I wouldn't be posting a duplicate. The conclusion of the proposal you linked to, however, is to indeed change the logger type to be an interface, and wait for Go2 to make that change.

I think my proposal is sufficiently different in that I'm suggesting a substantial change/expanding of the interface. Part of the reason for my suggesting this implies/requires the log.Logger type to be redefined as an interface already. Given that there seems to be little discussion about whether or not the type should be an interface, I think this issue could serve to discuss what that interface should look like.

[lpar]

I strongly support giving Go 2 a standard interface for leveled logging. As far as I can see #13182 is about giving Go 2 the current deficient logging API, but as an interface.

The problems I see with the current API are:

1. Lack of support for leveled logging. Even Google developers feel the need to have a non-standard logging library to get leveled logging, so I hope people will generally agree that we need leveled logging, and we can move on to bikeshedding about how many levels… ☺

2. Inability to handle structured logging of data.

3. Performance. Multiple logging libraries have implemented APIs which avoid Printf-like methods so that they can avoid the corresponding runtime overhead. I'm thinking of zerolog and zap here. It's obviously OK to provide Printf style methods, but if that's all you provide, people will still end up implementing non-standard APIs to handle fast structured logging.

4. Difficulty of implementing standard Unix conventions, where errors go to stderr and everything else goes to stdout.

I also don't think that a logger has any business implicitly terminating the program, and have never liked log.Fatal or log.Panic; and I dislike that the default date format is gratuitously non-standard rather than ISO 8601. Those are fixable given the right implementation of a standard interface, however.

[EVODelavega]

@lpar Because of point 1 under the problems you list I'm assuming you're talking about the current implemented log package (not the proposed interface I've shared here). I completely agree with you on the log levels. We need them, we all use them, and not using them leads to much unneeded pain and wasted time sifting through logs to see where an actual error occurred vs some leftover debug logging lines.

Same goes for structured logging and performance. Couldn't agree more, hence my sharing my thoughts here. I'm looking for feedback before I start hacking away at things.

4. Not sure what you're referring to. I prefer setting my logger to output to os.Stdout for everything, and just scrape the output and push that to elastic (ie typical FEK/ELK stack).

The only point I'd disagree with you is on the implicit terminating calls. I see little value in forcing people to write:

if err := doStuff(); err != nil {
    log.Fatal("An error occurred, exiting (%+v)", err)
    os.Exit(1)
}

As opposed to a simple:

if err := doSomething(); err != nil {
    log.Fatalf("An error occurred - exitting: %+v", err)
}

The fact that the func is called Fatal should make it obvious that it's a terminating call. I haven't used the log.Panic call at all though, like ever... don't know if that's a particularly useful thing to keep, and given that Go2 can break backwards compatibility I'd personally have no problems whatsoever with that call to be confined to the pages of Go's history.

[lpar]

I use Go to write programs which are called from crontabs, run by users at the command line, and run on cloud platforms. In those circumstances, the expected behavior is that errors go to stderr and regular output (such as progress messages) goes to stdout. Sure, if I'm stuffing everything into ELK I don't need to separate errors (and I generally want the output in something like JSON), but that's not usually the case for me, and I think we should make sure that the API is suitable for things like writing Unix utility programs and daemons.

Dave Cheney has set out the problems with log.Fatal. Given that there are so few situations where it's appropriate, I don't see that it has value to leave it in the API as a pitfall for beginners just for the sake of saving one line of code. The same applies to log.Panic.

[bonpibonpi]

I am negative to give levels to the logging interface.
The log level required by the project varies depending on the background.
For small commands and servers Info, Error, Fatal are sufficient,
Debug, Warning, perhaps Emerg and Crit etc may be necessary.
At least Unix syslog and Windows Eventlog have different levels.
Some people say there is no need other than Debug and Info.

The Go log package does not have levels, but third party are not the only choice.
We need a little work but solution by wrapping is a good enough approach.

GoPlayground and Upspin are good examples.
GoPlayground has Print, Error, and Fatal Level interfaces, and uses the standard logger wraped.
Upspin redefines the log package itself and has a standard logger for each level.

The GoPlayground example is simple and useful for small commands and servers that require less levels.
An example of Upspin has cost, but it is worthwhile on a large scale.
Third-party log packages may not meet your needs, but keep costs down.

The current Go can choose a tradeoff.

The level defined in the standard library gives a slight sense of security,
Gives great pain to those who do not meet the needs.
And the bloated interface is ugly.

The interface of Go is Acceptable.
In many cases it is more beautiful to define things that the user needs rather than the library.

[EVODelavega]

@bonpibonpi You raise a couple of valid points there, specifically around the syslog having different levels. I get the argument made for third party packages, that's why I'm using them. The reason for my posting this proposal was more to take advantage of Go's ecosystem being one that is fairly opinionated. So far, there's been a couple of times where there were several tools doing a similar job, and the community has fairly quickly adopted a single, standard tool (e.g. vendoring via glide, goop, trash, gopm, etc.. eventually resolved when dep became the official tool).

The current interface can be preserved, and even kept as a separate interface type to be embedded or whatever. That's just it: the log levels you refer to for syslog or windows eventlog don't have to be added to a single one-size-fits-all logging interface. There's nothing wrong with having a CLILog, ServerLog, and SysLog interface, is there?

This is definitely a discussion worth having, I think, if there's enough support for this proposal to gain traction, naturally.

Regards

[ianlancetaylor]

There have been attempts in the past to produce a standard logging interface. I think @rakyll knows something about that.

[rakyll]

@zombiezen has run comprehensive research in the past and can provide context on the historical attempts and feedback on this proposal.

[zombiezen]

The original discussion and design proposals are documented on golang-dev. Sarah's post in particular summed up our (Sarah Adams, Peter Bourgon, Chris Hines, Cory LaNou, Herbie Ong, and myself) findings:

The overall requirements for what end-users need is bifurcated into what an application and what a library needs for logging. The variance in efficiency and format of logging backends is so large so as to make generalizations not useful to a library. The best practice here should be that libraries (either standard library or third-party) expose a structured interface where appropriate (like net/http/httptrace) and that applications map the appropriate events to the specific logging backend of their choice. Creating a logging abstraction for a particular application or company is more optimal than trying to design an abstraction that gives a false sense of being uniformly optimal.

[zombiezen]

And separately, I'll add my two cents here: I think that the places in the standard library that use a *log.Logger as a parameter are incorrect. What I think should be considered for Go 2 is replacing these with interfaces to set better precedent. AFIACT, the particular occurrences are:

• net/http.Server.ErrorLog
• net/http/cgi.Handler.Logger
• net/http/httputil.ReverseProxy.ErrorLog

[EVODelavega]

@zombiezen I'll have a read through the links you provided. Just for the avoidance of doubt: I'm not proposing a single logger to be added to the standard lib. I've since actually encountered some situations where I've realised that a single logger interface would either be inadequate, or monstrously large. What I think a good addition to Go2 would be, is exactly what you refer to with your last comment: having distinct, standardised logger interfaces is what I think would really add value. The implementation of which is still very much reliant on individual needs, and can be easily done by one of the more popular third party logger packages.

The end goal should be to have plug-'n-play style logging everywhere, so you can pass an log.ErrorLogger to *sql.DB, for example:

db, err := sql.Open(driver, dsn, somelogger.New(opts...))

With slq.Open being some func along the lines of func Open(driver, dsn string, errLog log.ErrorLog) or something.

Not sure if I ought to update this proposal to reflect the change of focus, open a new one, or abandon it all together.