ewintr.nl

My take on logging in go

Note: the Go project has added structured logging to the standard library in 2023, rendering some of the content below outdated. Be sure to read this post and learn more about it.

The subject of logging comes up every now and then, in every group of developers. Apparently it is something to be opinionated about, like code formatting. Or to something complain about, like leaving off the cap of the toothpaste. If only there was a go fmt for logging. Or toothpaste.

Anyway, as with most things computing, I like logging to be simple and pragmatic. Over the years, these are the things I’ve come to consider important with this subject.

Levels

When thinking about what logging levels are appropriate, it helps to define the intended audience for a certain level and what information that audience should get out of it. In addition to that, it also helps to remember what goals and what information are already covered by other systems.

For instance, logging is not to be confused with:

If there are other systems in place to provide this functionality, adding information for it to the logs just increases the noise. If there are no other systems and you want to use logging for it, then make sure that appropriate procedurees are in place, or the information will still be noise. For instance, what use has the logging of a warning, when there is no-one who actually gets warned and people only see it when they happen to stumble upon it when they are looking for someting else?

What should be logged then and at what level? In this article, Dave Cheney makes a good argument to minimize the logging interface and he states that the only useful levels are debug and info. However, he acknowledges that errors should be logged too and since we try to add structure to ours logs (see next section), it would be strange to log an error as info and then later use another way to add the semantic information that it is, in fact, an error.

Together, this gives the following levels and their intended audience:

Structured logging and standard log messages

At minimum a log line is just a line of text. Preferably with a timestamp somewhere in it. But since there are a lot of them and they tend to grow into big haystacks that may or may not have a needle in them, it helps if we can use scripts and other automation to help us search and analyze them. Thus we want something that is easy to parse.

I am not in favor of using JSON for everything everywhere, but I think this is an appropriate use case. Every line should be a line of JSON with some fields. One of the benefits of using JSON structured logging is that it becomes much easier to give context to a messages by adding data. Context can be very helpful when searching and filtering the logs, but this only works well if the data is labeled explicitly.

Any serious logging library (see also the next section) will provide a way to add fields to a message. Use this as much as possible, because otherwise it will be hard to see from the logs what is message and what is context:

// without JSON structured logging
logger.Printf("response with status %d received", response.Code)

// output:
2021-01-01 12:00:00 response with status 400 received

// with JSON and levels, but without fields
logger.Infof("response with status %d received", response.Code)

// output:
{
  "level": "info",
  "message": "response with status 400 received",
  "time": "2021-01-01 12:00:00"
}

// with JSON, levels and fields
logger.With(log.Fields{
  "status": response.Code,
}).Info("response received")

// output:
{
  "level": "info",
  "status": 400,
  "message": "response received",
  "time": "2021-01-01 12:00:00"
}

The last example will be most useful when analyzing the logs, as we can now filter for an exact message (“response received“) and get all the variations of received status codes in one search. Usually, one does not know the exact reason that caused things to fail, that’s why we are analyzing after all. So we do not know the exact status code that we are looking for. Was the other server malfunctioning and did we receive a 500? Or is our password expired and did we receive a 401? When logging like the first couple of examples, we can only guess possible causes and try to predict the exact message before we can search for it. With the last approach, we just search for the message and then see what status was returned.

After that, we could either create a count of the different codes (x times 200, y times 500, etc) and see how they are distributed, or narrow down the search to a specific code. See this tutorial for some pointers on how to do some useful quick analyses on the commandline.

Errors are excellent candidates to put in a field. If the level of the message is error, there should be a field with key "error” present:

// verbose implementation
logger.WithFields(log.Fields{
  "error": err,
}).Error("something did not work")

// with shortcut method
logger.WithErr(err).Error("something did not work")

Wrapping loggers

Another way to add structure is by wrapping loggers. Most loggers implement method chaining to provide what is called a fluent interface. That is, most methods on the logger have a new logger instance as a return type. We can use this to gradually add context as we pass the logger along:

// in main.go
logger := log.NewLogger(os.Stdout).WithFields(log.Fields{
  "service": "someservice",
})

m := something.New(logger, ...)

// in something/something.go
type SomeThing struct{
  logger log.Logger
  ...
}

func New(logger log.Logger, ...) *SomeThing {
  ...
  return &SomeThing{
    logger: logger.WithFields(log.Fields{
      "package": "something",
    }),
    ...
  }
}

func (st *SomeThing) DoIt(...) {
  logger := st.logger.WithFields(
    "method": "doit",
  )
  ...
  logger.Info("something was done")
}

If you now ever encounter a message "something was done" in the logs, it will be accompanied by the fields "service":"someservice", "package":"something" and "method":"doit". It is not hard to imagine how this could help the debugging during an incident.

Advanced structuring

There are more possibilities to add context and information, as can be seen from this example from the go-kit log library:

var logger log.Logger
logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)

logger.Log("msg", "hello")

// Output:
// ts=2016-01-01T12:34:56Z caller=main.go:15 msg=hello

Here log.DefaultTimestampUTC and log.DefaultCaller are functions. With a logger that accepts a contextual function as a value, one can create any structure that might be interesting. The function gets evaluated when the message is logged and the output is what gets stored. This way it is possible to add custom timers, add stack traces, etc.

Injecting loggers versus returning errors

As can be seen in the examples above, when building context it helps to treat a logger as an instance of type Logger and use it it to create new instances, instead of relying on a single logger that is globally present. A natural consequence of this is that a logger should be a parameter that is passed around whenever necessary. At first sight it seems cumbersome and verbose to do that everywhere in your code.

However, it is not necessary to pass the logger to every part of the code, since not every part of the code has the need to log. If we examine a basic directory structure for Go projects and look what kind of packages each folder holds:

.
├── cmd             // the different programs/services
├── internal        // decoupled packages specific to this repository
└── pkg             // decoupled packages that may be imported by other projects

Then we see that every action is initiated somewhere in /cmd and that the packages in /internal and /pkg are supposed to be decoupled from the rest. We can get by with the rule of thumb that the logging should be done in /cmd and that the packages in /internal and in /pkg should return errors that may or may not get wrapped and may or may not get logged when they arrive in /cmd.

Ever had some external library messing up things because they decided just to log to Stdout the way they saw fit? Not very helpful. If you wrap external dependencies in an adapter, you can make sure that the errors also translate properly to the domain of your program. If a library really insists on having a logger and you still want to use it anyway, this is the place to add context.

Example implementation

An example of how you can adapt a regular logging library to these practices is the log package in my small personal go kit repository. There is an interface definition in log.go, together with two implementations, one for Logrus and one for the gokit.io log package, and an implementation suitable for use in testing.