Key/value logs in Go

I shipped GitHub's first user-facing Go app a month ago: the Releases API upload endpoint. It's a really simple, low traffic service to dip our toes in the Go waters. Before I could even think about shipping it though, I had to answer these questions:

• How can I deploy a Go app?
• Will it be fast enough?
• Will I have any visibility into it?

The first two questions are simple enough. I worked with some Ops people on getting Go support in our Boxen and Puppet recipes. Considering how much time this app would spend in network requests, I knew that raw execution speed wasn't going to be a factor. To help answer question 3, I wrote grohl, a combination logging, error reporting, and metrics library.

import "github.com/technoweenie/grohl"

A few months ago, we started using the scrolls Ruby gem for logging on GitHub.com. It's a simple logger that writes out key/value logs:

app=myapp deploy=production fn=trap signal=TERM at=exit status=0

Logs are then indexed, giving us the ability to search logs for the first time. The next thing we did was added a unique X-GitHub-Request-Id header to every API request. This same request is sent down to internal systems, exception reporters, and auditors. We can use this to trace user problems across the entire system.

I knew my Go app had to be tied into the same systems to give me visibility: our exception tracker, statsd to record metrics into Graphite, and our log index. I wrote grohl to be the single source of truth for the app. Its default behavior is to just log everything, with the expectation that something would process them. Relevant lines are indexed, metrics are graphed, and exceptions are reported.

At GitHub, we're not quite there yet. So, grohl exposes both an error reporting interface, and a statter interface (designed to work with g2s). Maybe you want to push metrics directly to statsd, or you want to push errors to a custom HTTP endpoint. It's also nice that I can double check my app's metrics and error reporting without having to spin up external services. They just show up in the development log like anything else.

Comments are on reddit.

One HTTP Handler to rule them all

Justinas Stankevičius wrote a post about writing HTTP middleware in Go. Having seen how Rack changed the Ruby web framework landscape, I'm glad Go has simple HTTP server interfaces baked in.

GitHub itself runs as a set of about 15 Rack middleware (depending on the exact environment that it boots in). They are setup in a nice declarative format:

# GitHub app middleware pipeline
use InvalidCookieDropper
use Rack::ContentTypeCleaner
use Rails::Rack::Static unless %w[staging production].include?(Rails.env)

# Enable Rack middleware for capturing (or generating) request id's
use Rack::RequestId

However, Rack actually assembles the objects like this:

InvalidCookieDropper.new(
  Rack::ContentTypeCleaner.new(
    Rack::RequestId.New(app)
  )
)

This wraps every request in a nested call stack, which gets exposed in any stack traces:

lib/rack/request_id.rb:20:in `call'
lib/rack/content_type_cleaner.rb:11:in `call'
lib/rack/invalid_cookie_dropper.rb:24:in `call'
lib/github/timer.rb:47:in `block in call'

go-httppipe uses an approach that simply loops through a slice of http.Handler objects, and returns after one of them calls WriteHeader().

pipe := httppipe.New(
  invalidcookiedropper.New(),
  contenttypecleaner.New()
  requestid.New(),
  myapp.New(),
)

http.Handle("/", pipe)

This is how http.StripPrefix currently wraps another handler:

func StripPrefix(prefix string, h Handler) Handler {
  if prefix == "" {
    return h
  }
  return HandlerFunc(func(w ResponseWriter, r *Request) {
    if p := strings.TrimPrefix(r.URL.Path, prefix); len(p) < len(r.URL.Path) {
      r.URL.Path = p
      h.ServeHTTP(w, r)
    } else {
      NotFound(w, r)
    }
  })
}

It could be rewritten like this:

type StripPrefixHandler struct {
  Prefix string
}

func (h *StripPrefixHandler) ServeHTTP(w ResponseWriter, r *Request) {
  if h.Prefix == "" {
    return
  }
  
  p := strings.TrimPrefix(r.URL.Path, h.Prefix)
  if len(p) < len(r.URL.Path) {
    r.URL.Path = p
  } else {
    NotFound(w, r)
  }
}

func StripPrefix(prefix string) Handler {
  return &StripPrefixHandler{prefix}
}

Notice that we don't have to worry about passing the response writer and request to the inner handler anymore.

Embedding Structs in Go

I've been toying with Go off and on for the last few months. I'm finally at a point where I'm using it in a real project at GitHub, so I've been exploring it in more detail. Yesterday I saw some duplicated code that could benefit from class inheritance. This isn't Ruby, so I eventually figured out that Go calls this "embedding." This is something I missed from my first run through the Effective Go book.

Let's start with a basic struct that serves as the super class.

type SuperStruct struct {
  PublicField string
  privateField string
}

func (s *SuperStruct) Foo() {
  fmt.Println(s.PublicField, s.privateField)
}

It's easy to tell what Foo() will do:

func main() {
  sup := &SuperStruct{"public", "private"}
  sub.Foo()
  // prints "public private\n"
}

What happens when we embed SuperStruct into SubStruct?

type SubStruct struct {
  CustomField string
  
  // Notice that we don't bother naming embedded struct field.
  *SuperStruct
}

At this point, SuperStruct's two fields (PublicField and privateField) and method (Foo()) are available in SubStruct. SubStruct is initialized a little differently though.

func main() {
  sup := &SuperStruct{"public", "private"}
  sub := &SubStruct{"custom", sup}
  
  // you can also initialize with specific field names:
  sub := &SubStruct{CustomField: "custom", SuperStruct: sup}
}

From here, we can access the SuperStruct fields and methods as if they were defined in SubStruct.

func main() {
  sup := &SuperStruct{"public", "private"}
  sub := &SubStruct{"custom", sup}
  sub.Foo()
  // prints "public private\n"
}

We can also access the inner SuperStruct if needed. You'd normally do this if you wanted to override a behavior of an embedded method.

func (s *SubStruct) Foo() {
  fmt.Println(s.CustomField, s.PublicField)
}

func main() {
  sup := &SuperStruct{"public", "private"}
  sub := &SubStruct{"custom", sup}
  sub.Foo()
  // prints "custom public\n"
}