Explain why Logger.log() returns error

[cep21]

Hi,

I think go-kit/kit/log reflects my personal thoughts on logging, but I am hesitant to use it directly due to Logger.log() returning an error. In my opinion errors are intended to be checked, not ignored. And it's unreasonable to ask users to check log messages. I feel a better philosophy is for the formatters/writers that eventually output messages to disk/tcp/stdout/etc to allow registering handlers for error types. Then, when I setup logging I can say "Here is a logger that logs JSON to a file. If there is an error, call this function (maybe try stdout or maybe trigger some application "debug me" state).

Maybe something like

type jsonLogger struct {
  io.Writer
  onError func(err error, keyvals ...interface{})
}

[cep21]

Another option is to turtles it all the way down

type jsonLogger struct {
  io.Writer
  onError func(err error) log.Logger
}

then you would call

if err := json.Marshall(obj); err != nil && onError != nil {
  onError(err).Log(keyvals)
}

This isn't so bad since at some point failures have to just be ignored (In my case, the last failure would set some debug bit that a monitoring system would check for).

[cep21]

As an example, there exist loggers that simply can't return errors. One such logger would be like this

type bitSetter struct {
  isSet int
}
func (b *bitSetter) Log(...keyvals interface{}) {
  if contains(keyvals, "state", "critical") {
    atomic.StoreInt32(isSet, 1)
  }
}

func (b *bitSetter) getPrometheusMetrics() prometheus.Metric {
  return prometheus.Metric("critical_state", atomic.LoadInt32(isSet))
}

For the above logger, my monitoring system would be able to tell me if it entered a critical state. Maybe this is good as a check of last resort if all the loggers are FUBAR (The disk mount is RO for example). It's impossible for this logger to error out, which implies to me errors are a consequence of individual loggers and not of logging as a concept.

[ChrisHines]

There is a lot to unpack here. In this post I will do my best to explain why the log.Logger.Log method returns an error. I will follow up in another post to present what I believe are more elegant solutions to the challenges you present.

In my opinion errors are intended to be checked, not ignored. And it's unreasonable to ask users to check log messages.

I agree, and yet we don't often see Go code like the following.

if _, err := fmt.Println("Hello, world!"); err != nil {
    // ???
}

Consider the case of the bytes.Buffer.Write method. It is declared like this:

// Write appends the contents of p to the buffer, growing the buffer as
// needed. The return value n is the length of p; err is always nil. If the
// buffer becomes too large, Write will panic with ErrTooLarge.
func (b *Buffer) Write(p []byte) (n int, err error)

Why does it return an error that is always nil? The answer is obvious, because implementing the io.Writer interface makes bytes.Buffer more useful. As a result of implementing io.Writer we can pass a *bytes.Buffer to any of the many functions that accept an io.Writer. On the other hand, it is clear that many io.Writer implementations need to return errors, so the interface is declared accordingly and bytes.Buffer simply does not utilize that part of the interface.

The io.Writer interface defines the fundamental interface for writing streams of bytes in Go. Similarly, our log.Logger interface defines the fundamental interface for recording streams of structured log data in Go kit.

Some loggers might return errors, others may never return errors, but the central interface must allow it. The value of implementing the central interface is greater than the loss of precision for the implementations that never return errors. We can follow the example of the standard library and simply document those cases that will always return nil errors.

More later...

[cep21]

I think go's built in library takes both approaches. This mismatch is probably related to the special function logging has vs other APIs. For example, the built in logging library has func (l *Logger) Print(v ...interface{}) and not func (l *Logger) Print(v ...interface{}) error, where func (l *Logger) Output(calldepth int, s string) error is used for people that really need an error. I've never actually seen it used, however.

I'm trying to think about what makes logging different than fmt.Println and bytes.Buffer.Write and I think it comes down to the following statement:

If I write an API that accepts an interface who's method returns an error, there is an implicit contract that I will or need to check the return code of that error.

If an object contained a bytes.Buffer or accepted one, then nobody expects me to check return codes of writing to that object. If however,it accepts io.Writer, then it's reasonable that it's expected I check all io.Write() calls and do some kind of logging or tracking if it returns an error.

There's a danger someone could write a logger that returns an error and expect people to check that error.

An example of the danger of ignoring error codes is your currently implemented json_logger.go If someone adds a log value that is unconvertable to JSON then they would end up with empty log messages because json.Encode() would return an error and the entire log message would be lost. This could at least be notifiable if people registered an error callback for the JSON logger.

As other evidence, most (all?) the other written logging libraries (including the log package) don't return errors on log methods and it's very unexpected if any of the Java logging libraries threw an exception (I don't know any that do).

[cep21]

Another perspective is to consider that Go is an implic­itly imple­mented interface language. So forget go-kit, forget the idea of logging, forget JSON and files and think of it entirely from the API owner's perspective.

I'm writing a zookeeper or kafka library and I need to do something with random types of events that are probably important for people to know about but I can't really handle. Or maybe I do handle them, but I should still tell someone about the event. TCP reconnects, etc. Perfect use case for logging. Now I need to decide what API I want to expose to the world for how they can pass me a logger.

From my perspective, does this API have a log method that returns an error or not? I think it makes the most sense for this API to not have a method that returns an error. If I communicate to the world via my exposed API that I want a logger that returns an error, then I'm implicitly communicating that I will handle errors returned by that function call. But since there's nothing I can do with those errors, it makes sense for me (again think about implicit interfaces and forget go-kit/logging/JSON/etc) to want a logger that does not return an error. That communicates via my API that whoever is passing me this logger should make it handle its own errors somehow.

I think this perspective holds true for most (all?) use cases of logging from an API writer's perspective.

I think if one removes themselves from trying to write a logging library and instead thinks of it from the consumers of the API's perspective that is trying to expose a logging mechanism, it makes more sense to want a logging interface that does not return an error.

[peterbourgon]

@cep21 Package log is designed to be used for more than simple application info/warning/error logging; it's suitable for log-structured data in an e.g. Lambda architecture, where each invocation is important. I agree with you that if we were doing only application logging the error would be more noise than signal. But the scope of the package is larger than that.

[cep21]

Lambda architecture

That makes a lot of sense to me. I can totally see how lambda may want a method that sends things that requires an error check on each invoation. However, I'm focusing here on a logging interface. People taking an io.Writer are expected to check error codes, but people expecting a logger interface do not. I think the quote* where each invocation is important* has two important assumptions

1. The only way to verify a call is to return an error.
   This doesn't have to be true. I gave two alternatives above. The current implementation is actually worse than this. By returning an error in the interface, you've guaranteed practically that errors will be ignored (given how logging libraries are used in practice). If instead logging did not return an error, then you've negotiated via API handling of the error in the logger implementation.
2. The caller knows it is logging to Lambda
   The caller doesn't know this. The caller is taking an interface.

Since logging is an interface and go is an implicit interface language, we should define the interface we want API writers to accept.

Can you give an example of a library written in go that has wide usage, does logging, and would be improved by taking a logger who's Logger.Log() method is checked on each invocation?

[ChrisHines]

@cep21 I believe we agree that in many cases call sites that originate log events do not want to handle errors and indeed probably don't have a good way to handle them anyway. I believe we also agree that errors will occur when serializing and transmitting or persisting log events.

Let's take a look at how other logging packages transmit errors (or not).

stdlib log

type Logger struct {
    ...
    out    io.Writer  // destination for output
    ...
}

func (l *Logger) Print(v ...interface{}) {
    l.Output(2, fmt.Sprint(v...))
}

func (l *Logger) Output(calldepth int, s string) error {
    ...
    _, err := l.out.Write(l.buf)
    return err
}

We can see from the above code excerpts that the standard log package simply discards the errors if you call Logger.Print or its siblings. If you care about handling the error returned from the io.Writer you either need to do your own formatting and call Logger.Output directly or perhaps give Logger.SetOutput an io.Writer that handles errors the way you want.

log15

// A Logger writes key/value pairs to a Handler
type Logger interface {
    ...
    // SetHandler updates the logger to write records to the specified handler.
    SetHandler(h Handler)

    // Log a message at the given level with context key/value pairs
    Debug(msg string, ctx ...interface{})
    ... etc ...
}

// A Logger prints its log records by writing to a Handler.
// The Handler interface defines where and how log records are written.
// Handlers are composable, providing you great flexibility in combining
// them to achieve the logging structure that suits your applications.
type Handler interface {
    Log(r *Record) error
}

type logger struct {
    ...
    // swapHandler wraps another handler that may be swapped out
    // dynamically at runtime in a thread-safe fashion.
    h   *swapHandler
}

func (l *logger) Debug(msg string, ctx ...interface{}) {
    l.write(msg, LvlDebug, ctx)
}

func (l *logger) write(msg string, lvl Lvl, ctx []interface{}) {
    l.h.Log(&Record{ ... })
}

We can see that the log15 package defines two interfaces. The higher level interface, Logger, does not return errors, while the lower level Handler interface does. Like the standard library, log15 ignores errors at this level (in the logger.write method when calling l.h.Log). But that's not the end of the story for log15.

Log15 includes a FailoverHandler (follow the link for full docs). FailoverHandler wraps a slice of handlers that it tries in order until one succeeds. If the last handler in the slice were to always return a nil error then the FailoverHandler will also always return nil.

Go kit log

The Go kit log package takes quite a bit of inspiration from log15 and tries to simplify the API as much as possible. Logger is the sole central interface of the package. It provides the same degree of composability as log15's Handler but is more general.

Go kit leans more heavily on the practice of wrapping or decorating loggers with other loggers. This choice dramatically simplifies the API without loss of expression, but it also means that Logger.Log must return an error. I don't consider that a problem.

If, when using Go kit, you want to ensure all logging errors are handled in some way then I believe the correct approach is to write a Logger decorator that handles errors returned by a wrapped logger as desired.

I believe that when doing application logging, calls to Logger.Log should ignore the errors and rely on main.main to provide a Logger implementation that does the right thing for that application. Perhaps it installs a MustLogger that panics on all errors, or perhaps it installs a FailoverLogger configured with your bitSetter as the logger of last resort.

I started working on some "meta" loggers about three months ago, but I haven't decided if it is worth adding them to the main repo. Here is my take on FailoverLogger copied from the branch where I was playing with the ideas. (This code is not fully tested.)

// NewFailoverLogger returns a Logger that logs all log events to the first
// provided logger. If the first logger returns an error the log event is
// logged to the second logger, and so on until one of the loggers succeeds.
// For each logging error the log event is augmented with an additional key of
// the form "failover_err_{idx}" and the error as its value before the log
// event is sent to the next logger in the chain.
func NewFailoverLogger(loggers ...Logger) Logger {
    return &failoverLogger{
        loggers: append([]Logger{}, loggers...),
    }
}

func (l *failoverLogger) Log(keyvals ...interface{}) error {
    kvs := keyvals[:len(keyvals):len(keyvals)]
    if len(kvs)%2 != 0 {
        kvs = append(kvs, ErrMissingValue)
    }

    var err error
    for i, l := range l.loggers {
        err = l.Log(kvs...)
        if err == nil {
            return nil
        }
        kvs = append(kvs, fmt.Sprintf("failover_err_%d", i), err)
    }
    return err
}

[cep21]

Thanks for entertaining this discussion :)

at how other logging packages transmit errors

I think we both agree that other log packages handle errors in a suboptimal way. My primary point is that their main Log method does not return an error.

I believe that when doing application logging, calls to Logger.Log should ignore the errors and rely on main.main to provide a Logger implementation that does the right thing for that application.

I think this is the strongest disagreement. There are two philosophies here. The first is Define an API that can be abused and document how to use it correctly vs Define an API that limits abuse. I strongly prefer the later case, which is why I think Log() without returning an error is the correct approach.

As an example, if I'm writing a ZooKeeper library and I need a place to log things and I don't want to check error codes, then the best API for me to expose in an implicitly typed language is Log() without an error. In this case, I have limited a vector to abuse the API.

Ignoring errors is really dangerous. If I were to write a top 5 Things to know as a new Go programmer to write fault tolerant systems that list would include Never ignore errors returned by interface function calls

[ChrisHines]

Perhaps the disconnect here is the difference between the Go kit Logger interface, and what a ZooKeeper library should expose. I would be interested in what you think of the discussion we had in #42.

A ZooKeeper package that wants to provide logging output and enforce a no errors from logging policy can export its own Logger interface. It would then be main.main's responsibility to provide an implementation of that interface. If main.main is using Go kit logging, it would need to provide an adapter that filtered out any errors that bubble up from the lower levels. The code might look something like the following.

package zookeeper

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

func (z *Client) SetLogger(logger Logger) {
    z.logger = logger
}

func (z *Client) Get(key string) string {
    ...
    z.logger.Log("event", "sending request")
    ...
    z.logger.Log("event", "received response")
    ...
}

package main

import "os"
import "zookeeper"
import "github.com/go-kit/kit/log"

func main() {
    logFormat := log.LogfmtLogger(os.Stdout)
    logger = log.LoggerFunc(func (keyvals ...interface{}) error {
        if err := logFormat.Log(keyvals...); err != nil {
            // handle error
        }
        return nil
    })

    zk := zookeeper.Open()
    zk.SetLogger(&zkLogger{logger})

    ...
}

type zkLogger struct {
    logger log.Logger
}

func (l *zkLogger) Log(keyvals ...interface{}) {
    l.logger.Log(keyvals...)
}

[cep21]

can export its own Logger interface

I totally agree. And I think now we're getting somewhere. Since this is the perspective of go-kit's other libraries itself, then why doesn't go-kit dogfood this very advice?

None of the following libraries ever check log errors. If they aren't checking log errors, then why aren't they designed with an API that accepts a non error logging Logger? Why aren't they requiring this same wrapper?

https://github.com/go-kit/kit/blob/master/loadbalancer/dnssrv/publisher.go
https://github.com/go-kit/kit/blob/master/transport/http/server.go
... (many others as examples)

[peterbourgon]

why doesn't go-kit dogfood this very advice?

It's OK for client code to ignore errors, if the error doesn't introduce invalid state into the program, and the client code has no meaningful way to act on that error. Ignoring the error from an application log invocation fits both of these criteria.

Introducing and using this

type ApplicationLogger interface {
    Log(keyvals ...interface{}) // no error
}

to wrap this

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

is largely unnecessary noise.

[ChrisHines]

A ZooKeeper package that wants to provide logging output and enforce a no errors from logging policy can export its own Logger interface.

why doesn't go-kit dogfood this very advice?

I wasn't presenting that idea as advice, but as a choice that a package author could make if they held strong opinions on this topic. I stated my personal opinion above which align with @peterbourgon's comments.

[cep21]

Thanks for entertaining this conversation :)

I think I understand your perspective, I just disagree with it lots. But that's ok, right!? Plus, it's really difficult to disagree with Benedict Cumberbatch's profile photo. I think you've fallen on something pretty useful with the Log vararg syntax and the context, and totally agree with the lack of levels. I'll probably replicate something similar. Thanks for the MIT license!

[ChrisHines]

@cep21 Thanks for raising the question and challenging assumptions. :)