Structured Logging in Golang

Out of the box, golang provides the stdlib/log package. It provides “printf” style logging. A template string is used along with a list of arguments, and a log message is generated:

log.Printf("user %d wasn't found", 1234)
// user 1234 wasn't found

This dynamically generated message is easy and convenient but has a number of issues involving storage, searching, and consistency.

Structured logging solves these problems by replacing the printf message template with named-fields. They come in two styles:

// vargargs style
log.Info("user not found", "userid", 1234)

// or using another popular syntax
log.WithField("userid", 1234).Info("user not found")

The output is a list of key-value pairs followed by the static message:

// userid=1234 msg="user not found"

Most if not all structured loggers output in some serializable format such as JSON or logfmt. That makes it trivial to export or import data into Splunk or Kibana.

Solving Problems with Grep

Because the message is a static string, searching, sorting, aggregating, and counting various types of different error messages can be solved using grep. Both in the log file (what happened), and in code (where did it happen). If your problem can be reduced to grep, you win. For example:

// sample message
msg="user not found" id=1234

// How many times did this happen?
grep -c "user not found" mylogfile.log

// what happened with user id "1234" ?
grep 'id=1234' mylogfile.log

// what line of code emitted this?
find . -name '*.go' | xargs grep "user not found"

One can still do the same with a message in the form of “user id 1234 not found" but it’s a lot harder and error prone.

Better English, Better Internationalization

Another benefit to structured logging and the use of static string for a message is that the message becomes a lot simpler grammatically. Plurals and special forms typically go away (1 user vs. 2 users). The language becomes a lot more consistent, e.g. “user not found” vs. “user 1234 not found” vs “unable to find user 1234” vs “couldn’t find user 1234”. As mentioned above this make searching easier, but also makes for easier reading, especially for if English is not their primary language. And if you end up internationalizing the application, “user not found” is a lot easier to translate than a dynamic string.

Context Logging

Most structured loggers in golang also provide a helper called “context logging”. This allows you to pre populate some fields so critical data doesn’t need to be repeated. It also make the code more readable.

func setupUser(uid int) {
   logger = logger.With("userid", uid)
   logger.Debug("looking up user")
   // ...
   logger.Debug("updating record")
}

// userid=1234 msg="looking up user"
// userid=1234 msg="updating record"

Golang

As mentioned the standard log in golang doesn’t support structured logging. However many if not most third party packages support it. To get started, two good general packages are sirupus/log and apex/log. For high performance logging, see uber/zap or rs/zerolog. More details are on found in Logging Packages in Golang.

Log on...