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:
- calling out to external services, like a database
- making key business logic decisions
- 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! :) -