Using Go's 'context' library for logging

There’s many ways to make sure that a service is operating correctly under the hood. Let’s talk about one standard approach - logging - and how context can help you turn your logs into rich sources of insight.

Initially, you might start with the built-in log library, and its Printf inteface:

    package somelibrary

import "log"

func DoSomethingAwesome(so, param string, wow int) {
// ... awesomeness ...
log.Printf("did something %s awesome with %v (%d times)",
so, param, wow)
}


This writes to “standard error”. You test this in your program and it works out great for getting the feature working:

2016/12/01 11:48:50 handling /doit for Bert
2016/12/01 11:48:50 did something so awesome with param (2 times)
2016/12/01 11:48:50 finished handling /doit for Bert


But then later once you deploy your code to production, you look at your logs and see this sort of thing:

2016/12/01 11:49:12 handling /doit request for Bert
2016/12/01 11:49:12 handling /doit request for Alex
2016/12/01 11:49:12 did something totally awesome with cheese (3 times)
2016/12/01 11:49:12 did something so awesome with param (2 times)
2016/12/01 11:49:12 finished handling /doit for Alex
2016/12/01 11:49:12 finished handling /doit for Bert


Alex reports something went wrong. But because your program is a high performance parallelized wonder, you can’t be sure which line relates to her request.

Tagging requests with request IDs

When you solved this problem in blub, it was pretty easy: you just assigned a request ID to the request, and then some magic library made that request ID log in every line logged anywhere in the program.

So how can we do this in go?

First, let’s ditch the standard log library, which is horribly unstructured, and use Uber’s zap logger. You could equally well do this with logrus or something like that, of course.

Then we set up a local logging library.

    package logging

import (
"context"

"github.com/uber-go/zap"
)

type loggerKeyType int
const loggerKey loggerKeyType = iota

var logger zap.Logger

func init() {
// a fallback/root logger for events without context
logger = zap.New(
zap.NewJSONEncoder(zap.TimeFormatter(TimestampField)),
zap.Fields(zap.Int("pid", os.Getpid()),
zap.String("exe", path.Base(os.Args[0]))),
)
}

// NewContext returns a context has a zap logger with the extra fields added
func NewContext(ctx context.Context, fields ...zap.Field) context.Context {
return context.WithValue(ctx, loggerKey, WithContext(ctx).With(fields...))
}

// WithContext returns a zap logger with as much context as possible
func WithContext(ctx context.Context) zap.Logger {
if ctx == nil {
return logger
}
if ctxLogger, ok := ctx.Value(loggerKey).(zap.Logger); ok {
return ctxLogger
} else {
return logger
}
}


Now, the program can log the request ID, just by using this logging.WithContext function:

    package somelibrary

import (
"context"
"github.com/uber-go/zap"
"github.com/FooStartup/logging"
)

func DoSomethingAwesome(ctx context.Context, so, param string, wow int) {
// ... awesomeness ...
logging.WithContext(ctx).Info("did something awesome",
zap.String("so", so), zap.String("param", param),
zap.Int("wow", wow"))
}


For this to work, the caller (presumably whatever calls the request handler) just calls the NewContext function to add the new fields, and passes the new, specialized context down:

    package yourapp

import (
"context"
"net/http"
"github.com/uber-go/zap"
"github.com/FooStartup/logging"
"github.com/FooStartup/somelibrary"
"github.com/pborman/uuid"
)

var httpContext = context.Background()

func RequestHandler(w http.ResponseWriter, r *http.Request) {
rqId := uuid.NewRandom()
rqCtx := logging.NewContext(httpContext, zap.Stringer("rqId", rqId))
logger = logging.WithContext(rqCtx)
logger.Info("handling /doit request", zap.String("for", user))
somelbrary.DoSomethingAwesome(rqCtx, ...)
logger.Info("finished handling /doit request")
}


Now, the requests will come through tagged!

2016/12/01 14:49:12 [INFO] handling /doit request rqId="aad6dcde..." for="Bert"
2016/12/01 14:49:12 [INFO] handling /doit request rqId="7f5b859a..." for="Alex"
2016/12/01 14:49:12 [INFO] did something awesome rqId="aad6dcde..." so="totally" param="cheese" wow="3"
2016/12/01 14:49:12 [INFO] did something awesome rqId="7f5b859a..." so="so" param="param" wow="2"
2016/12/01 14:49:12 [INFO] finished handling /doit request rqId="7f5b859a..."
2016/12/01 14:49:12 [INFO] finished handling /doit request rqId="7f5b859a..."


It’s now possible to see which line was handled by each request handler, even through they are arriving in the log interleaved with each other.

Wait, so what is context.WithValue doing? Does it return a copy?!

A good conceptual model of context’s value storage is a map from anything (interface{}) to anything else (interface{}). context.WithValue returns a new context object which will return the value you poked in when you look up via the key you poked it into using .Value.

Similarly to a map with a key interface{}, lookup in a context is a comparison where the value and the type of the key are matched exactly. Using a custom int type fits this bill perfectly, and means that the value lookup is very fast: normally just comparing one pointer (to the type structure) and one value: both single machine words.

Each context object is also immutable, although the values in it don’t necessarily have to be. The way to update maps with immutable objects in functional languages like Erlang is to create a new one with the new key added, and this is something like what context.WithValue does. It’s actually a singly linked list, and each link only holds a single key. It looks it up, and if it doesn’t find it, it passes it to the parent.

What this immutability means is that it can be safely shared - across goroutines, functions etc, and the state is only ever additive. Important information that you add is rolled back as the functions return. It also makes it very cacheline friendly for decent multi-core performance.

So, what happens if the key isn’t set? Nil Pointer Panic?

Values not being set in the context is explicitly encouraged. If you try to fetch from the context and the key is not set, you’ll get nil back instead.

Did I say “encouraged”? What I actually mean is, if your function doesn’t work at all unless magic values are poked into the context first, you are almost certainly abusing context.

You should always try to cast the value back to the type you expected using the two-return form of casting, which returns a bool as a second return value which is only true if the typecast was successful.

That’s this part:

    if ctxLogger, ok := ctx.Value(loggerKey).(zap.Logger); ok {
return ctxLogger
} else {
return logger
}


If the logger was not passed into the context, then it just returns the global one.

Then just refactor everything

One thing I glossed over above was that the function signature changed:

    func DoSomethingAwesome(so, param string, wow int) {


became:

    func DoSomethingAwesome(ctx context.Context, so, param string, wow int) {


This might strike you at first as a bit ugly; having to pass an extra argument down through callers?! But consider how you’d have to implement this if you didn’t do this: you’d have to pass down a zap.Logger. And then, later, when you wanted to pass down some kind of profiling object, you’d need to pass that down, too. It’s a recipe for madness.

The nice thing about using context for this is that a single extra argument can cover an unlimited number of cut-across development patterns.

As such, a maxim I’ve adopted about this is: there is no harm in any function taking and passing down context objects. Basically any function which is doing anything non-trivial:

1. calling out to external services, like a database
2. making key business logic decisions
3. producing side effects

These types of functions can accept a ctx, even if they do nothing with it or merely pass it down the stack.

Tired? Take a breather with context.TODO()

There’s a couple of blank, starting context objects: context.Background() and context.TODO().

The first is supposed to be used at what you consider to be the “top level” of your program. The ideal state is where the main creates a background context, maybe tags it with the program name or something and then passes it into every single worker and routine that it starts for their specialization.

However, in a large established codebase, it isn’t that simple. Enter context.TODO(). If you’re calling a function which has had the context.Context parameter added, but the caller doesn’t have it passed down to it, you can use context.TODO(). If you’ve been correctly making sure that your functions degrade gracefully without a populated context, this will help you be able to gradually cover your codebase with contextual awareness.

And then, you’ll finally have matched Blub for its logging ability. But at 1000 times the speed! :) -