Our way to Go

At Dailymotion we embraced Go about a year ago. Most of our new back end projects are now using this young but still very powerful language. We like its simplicity, its performance and its static type checking.

We have certainly made most of the mistakes every new Go user make. We didn’t understand the power of interfaces at first, used and abused channels, designed new libraries badly and tested most of the “web frameworks” before coming to the conclusion that the Go standard library already has most of what we need.

As a result, each project ended up with a different combination of muxers and middleware managers. We have some Goji here and some httprouter there. Some use Negroni and others do not. This isn't really a problem, most middleware handlers will work with any of these tools until they have to pass some data to their sub handlers.

The (lack of) context

Most Go “web frameworks” try to solve the same issue: How can a middleware handler pass data to its sub handlers? It’s a bit sad the standard library didn’t nail this at the beginning. And it’s surprising because we know that Google had a solution for years to this specific issue; it has even been open sourced on golang.org/x via the net/context package. It is even mandatory at Google to pass a net/context to any networked code if you want it merged.

Despite being open sourced, net/context doesn’t get the love it deserves. We have ctxhttp to perform HTTP requests with a deadline, but there’s still no way to easily use net/context with HTTP handlers. That is mainly because the standard library lacks a net/context-aware http.Handler interface.

Across all our Go projects, we keep running into the same problems: how do we handle logging and instrumentation, that carry request context or environment data, without depending on globals or writing boring boiler plate code?

Our logs are JSON objects sent to ELK and our metrics are sent to Datadog with extensive use of tagging. We want to be able to write:

log.Errorf("An error occurred: %v", err)  

and obtain something like this:

{
  "message": "An error occurred: some error",
  "uri": "/some/path",
  "remote_ip": "127.34.56.78",
  "user_agent": "Mozilla…",
  "file": "path/to/file.go:23",
  "role": "service-name",
  "host": "serv-123"
}

Some data are related to the service, others to the host its running on, and the rest provide the context of the current request.

We could have done this by creating a logging and stats middleware handler for Goji and then issue a decree that this is framework for everything. But Goji doesn’t use net/context and we heavily believe in it. The net/context package provides not only the ability to carry data between middleware handlers but it also carries a deadline. If you write micro services that interact with other networked components, fine-grained deadline management is crucial. In the same way that Google is imposing it, we are willing to enforce the use of net/context everywhere in our Go stack.

Go kit, a good idea?

And then Go-kit showed up. It looked pretty promising at first. net/context is first class citizen, it has a log and metrics package and even a rate limiter and circuit breaker that may replace some in-house code.

We tested it, and despite having some very good ideas, it tries to solve an issue we don’t have: transport/serialization pluggability. It sounds great to think that you could switch from HTTP/JSON to gRPC without rewriting your logic. But this comes with a lot of boiler plate code and boring type assertions we are not comfortable with. And in real life, we never change the transport of an existing service.

As a web company that loves HTTP/JSON for its simplicity, inherent cacheability and the ease of debugging. We often play with Cache-Control and ETag headers, and the idea that something could prevent us from touching the HTTP layer for our own good doesn’t work for us.

Introducing xhandler, xlog and xstats

So we kept some ideas from Go-kit but without trying to abstract HTTP — on the contrary — and built some simple packages that solve only one issue at a time.

First, we needed a way to bridge our net/context-aware handlers with standard Go HTTP handlers. We wanted to keep the freedom of using the muxer of our choice, or no muxer at all, when needed. We called this package xhandler and it is now open source. Some optional but handy middleware handlers are bundled to manage context timeout and auto cancelation of the context when the client disconnects. Check it out!

From that, we created two net/context-aware middleware handlers for logging and instrumentation, named xlog and xstats respectively. Both packages work roughly the same way: they create a per-request instance of themselves and store it in net/context so you can use it in lower layers. Some optional middleware handlers can be stacked to append common request contexts to their environment such as remote ip or user agent.

Installation is pretty straightforward:

// Chain is a helper for middleware management
c := xhandler.Chain{}

// Setup the logger handler
lh := xlog.NewHandler(xlog.LevelDebug, xh)

// Set some global environment fields
host, _ := os.Hostname()  
lh.SetFields(xlog.F{  
    "role": "my-service",
    "host": host,
})

// Set logger output to local syslog
// See xlog's doc for more output options
lh.SetOutput(xlog.NewSyslogOutput("", "", ""))

c.UseC(lh.HandlerC)

// Use some optional middleware handlers to add some
// request environment fields to our logs
c.UseC(xlog.RemoteAddrHandler("remote_ip"))  
c.UseC(xlog.UserAgentHandler("user_agent"))  
c.UseC(xlog.RefererHandler("referer"))

// Route and ship it
http.Handle("/", c.Handler(yourContextAwareHandler{}))

if err := http.ListenAndServe(":8080", nil); err != nil {  
    log.Fatal(err)
}

Then in your handlers you can access the logger from the net/context as follows:

log := xlog.FromContext(ctx)  
log.Info("A message")  

Or the same in one line with some additional fields:

xlog.FromContext(ctx).Info("A message", xlog.F{"with": "some optional fields"})  

The result of this last log would be:

{
  "level": "info",
  "message": "A message",
  "uri": "/some/path",
  "remote_ip": "127.34.56.78",
  "user_agent": "Mozilla…",
  "role": "my-service",
  "host": "serv-123",
  "file": "file.go:23"
}

The return of xlog.FromContext(ctx) can be used safely without testing for nil pointers. Even if the xlog.Handler is not installed in your middleware chain, xlog.FromContext(ctx) will always return a usable no-op logger.

As a bonus, both packages come with composable output settings:

lh.SetOutput(xlog.MultiOutput{  
    // Output interesting messages to console
    xlog.FilterOutput{
        Cond: func(fields map[string]interface{}) bool {
            val, found := fields["type"]
            return found && val == "interesting"
        },
        Output: xlog.NewConsoleOutput(),
    },
    // Also setup by-level loggers
    xlog.LevelOutput{
        // Send debug messages to console
        Debug: xlog.NewConsoleOutput(),
    },
    // End finally send everything over syslog
    xlog.NewSyslogOutput("", "", ""),
})

We are progressively adding those tools to all of our Go services in order to enjoy some uniform and easy reporting.

References