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` interface:
This writes to “standard error”. You test this in your program and
it works out great for getting the feature working:
But then later once you deploy your code to production, you look at
your logs and see this sort of thing:
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.
Now, the program can log the request ID, just by using this
`logging.WithContext` function:
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:
Now, the requests will come through tagged!
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 the logger was not passed into the context, then it just returns
the global one instead of exploding.
…then just refactor everything
One thing I glossed over above was that the function signature changed:
became:
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 should have one:
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! :)
