Menu
Groove.id blog

Getting Real About Structured Logging

by Ross Kinder

Structured logging is all the rage among the skinny-jeans set. The go community have come up with a bunch of loggers that seem to encourage the model that an app should emit lines of JSON as logs. But is this approach really structured?

Say you configure logrus to emit JSON and scatter your code with stuff like this:

func main() {
  log.WithFields(log.Fields{
    "animal": "walrus",
  }).Info("A walrus appears")
}

When we did this we ended up with log messages that spelled fields wrong. Like, some places we spelled it animal and other places Animal and still other places AnimalID. This type of mistake was hard to detect in code review, and we certainly weren’t writing tests that our code produced log messages correctly (maybe we should have been!).

What we’ve done is produce logs that are formatted but not structured.

A humble proposal for an alternative pattern: make a struct that encompasses every log message your app can produce, and emit it everywhere:

package log

// Message represents a log message emitted by the app
type Message struct {
    Time  time.Time
    Error string    `json:",omitempty"`
    HTTP  *HTTP     `json:",omitempty"`
}

type HTTP struct {
    URI        string
    Method     string
    Handler    string
    StatusCode string
}

Now when you emit a log message, it looks a bit like this:

func HandleCount(w http.ResponseWriter, r *http.Request) {
	count, err := strconv.Atoi(r.FormValue("c"))
	if err != nil {
		lm := log.Message{
			Time: time.Now(),
			HTTP: &log.HTTP{
				URI:        r.RequestURI,
				Method:     r.Method,
				Handler:    "HandleCount",
				StatusCode: http.StatusBadRequest,
			},
			Error: err.Error(),
		}
		json.NewEncoder(os.Stderr).Encode(lm)

		http.Error(w, err.Error(), http.StatusBadRequest)
		return
	}

	// …
}

The end result is an application that emits log messages that are still easy to parse, but also consistent and structured.

Of course you wouldn’t really write code like the code I’ve shown, would you? We've found ourselves building helpers to turn internal objects into log messages:

func NewHTTP(r *http.Request) *HTTP {
	return &HTTP{
		URI:    r.RequestURI,
		Method: r.Method,
	}
}

Or for writing:

func (m Message) WriteTo(w io.Writer) (int, error) {
	return json.NewEncoder(w).Write(m)
}

And we can also write helpers to attach a log message to a context.Context, build the message throughout handling the request, and emit it at the end:

func HandleRequest(w http.ResponseWriter, r *http.Request) {
	m := &log.Message{}
	ctx = log.ContextWith(ctx, m)
	defer m.WriteTo(os.Stderr)

	// … handle the request
}

If you take this approach the structure of your logs is going to be very specific to your application, so this approach doesn’t lend itself to building a library per se, but some patterns emerge.

We have a package called log that contains a structure Message that represents the root object. Different application components have subpackages called things like foolog and barlog, each of which tends to contain a structure called Message. Our log package imports foolog and barlog so that log.Message can have fields for foolog.Message and barlog.Message. (foolog has to be in a different package to avoid import cycles.)

In ourapp/log/message.go:

package log

import (
	"thing/foo/foolog"
	"thing/bar/barlog"
)

type Message struct {
 	Foo *foolog.Message
	Bar *barlog.Message
}

In ourapp/foo/foolog/message.go:

package foolog

type Message struct {
	// things specific to foo
}

Go has a great type system, and we've found it super useful to take advantage of it to produce true structured logs.