Tracing Request IDs

Why requests need an identity

A single page load in Heroku's Dashboard passes through three separate components before it returns an app list; a git push heroku master touches closer to six. That kind of service-oriented decomposition pays off logistically, but it makes production debugging considerably harder.

Request IDs are one of the cheapest tools for getting visibility back. The idea — shared with Twitter's Zipkin, though far lighter, and with the Route 53 troubleshooting technique — is to group everything belonging to a request as it threads through a distributed architecture. Two things come out of it:

• Events can be tagged, so a complete report of what happened, and when, in every component touched can be assembled.
• An identifier is exposed to users — internal or external — who can hand it back when reporting a specific problem.

The identifier itself is a UUID generated when the request begins and kept for its lifetime. In Rack this is a small middleware:

class Middleware::Instruments
  def initialize(app)
    @app = app
  end

  def call(env)
    env["REQUEST_ID"] = SecureRandom.uuid
    @app.call(env)
  end
end

Application logging includes that identifier alongside each event; in Sinatra a helper handles it:

def log(action, data={})
  data.merge!(request_id: request.env["REQUEST_ID"])
  ...
end

A correctly instrumented request then emits a stream where every line carries the request ID:

app=api authenticate elapsed=0.001 request_id=9d5ccdbe-6a5c-4da7-8762-8fb627a020a4
app=api rate_limit elapsed=0.001 request_id=9d5ccdbe-6a5c-4da7-8762-8fb627a020a4
app=api provision_token elapsed=0.003 request_id=9d5ccdbe-6a5c-4da7-8762-8fb627a020a4
app=api serialize elapsed=0.000 request_id=9d5ccdbe-6a5c-4da7-8762-8fb627a020a4
app=api response status=201 elapsed=0.005 request_id=9d5ccdbe-6a5c-4da7-8762-8fb627a020a4

Draining log streams into Splunk gives a central place to pull back everything belonging to one request ID:

9d5ccdbe-6a5c-4da7-8762-8fb627a020a4

Platform-generated and composed IDs

You don't necessarily have to mint the identifier yourself. Heroku's routing layer can generate a request ID, which means platform-generated log events can carry a tag too; the value arrives in an incoming header:

def log(action, data={})
  data.merge!(request_id: request.env["HTTP_HEROKU_REQUEST_ID"])
  ...
end

That covers a single app. The composed case — several apps calling one another — is where the concept gets extended: callers inject their own request ID through a request header.

api = Excon.new("https://api.heroku.com", headers: {
  "Request-ID" => request.env["REQUEST_ID"]
})
api.post("/oauth/tokens", expects: 201)

The callee validates the incoming ID and, when it looks legitimate, tags its requests with that value in addition to one it generates itself. A request spanning multiple apps is therefore traceable as a group, while every app retains an individual trace for each of its own requests.

def call(env)
  env["REQUEST_ID"] = SecureRandom.uuid
  if env["HTTP_REQUEST_ID"] =~ UUID_PATTERN
    env["REQUEST_ID"] += "," + env["HTTP_REQUEST_ID"]
  end
  @app.call(env)
end

Events from the composed apps are then tagged with all of the generated IDs:

app=id session_check elapsed=0.000 request_id=4edef22b...
app=api authenticate elapsed=0.001 request_id=9d5ccdbe...,4edef22b...
app=api rate_limit elapsed=0.001 request_id=9d5ccdbe...,4edef22b...
app=api provision_token elapsed=0.003 request_id=9d5ccdbe...,4edef22b...
app=api serialize elapsed=0.000 request_id=9d5ccdbe...,4edef22b...
app=api response status=201 elapsed=0.005 request_id=9d5ccdbe...,4edef22b...
app=id response status=200 elapsed=0.010 request_id=4edef22b...

Querying Splunk with the top-level request ID returns log events from every composed app. Splunk is not the only option here — Papertrail and similar services do the same job.

Adjustments worth making

The middleware pattern takes a minor modification so that arbitrarily many request IDs can be injected, which is what you need to follow a request across three or more composed services.

def call(env)
  env["REQUEST_ID"] = SecureRandom.uuid
  if env["HTTP_REQUEST_ID"]
    request_ids = env["HTTP_REQUEST_ID"].split(",").
      select { |id| id =~ UUID_PATTERN }
    env["REQUEST_ID"] = (env["REQUEST_ID"] + request_ids).join(",")
  end
  @app.call(env)
end

Emitting the request ID as a response header makes individual requests easier to pick out and debug later on:

def call(env)
  request_id = SecureRandom.uuid
  ...
  status, headers, response = @app.call(env)
  headers["Request-ID"] = request_id
  [status, headers, response]
end

curl -i https://api.example.com/hello
...
Request-ID: 9d5ccdbe-6a5c-4da7-8762-8fb627a020a4
...

Heroku's V3 platform API returns a request ID with every response.

Where a context-sensitive helper like Sinatra's is architecturally awkward — likely in a larger application — logging can pull from a thread-safe request store instead:

# request store that keys a hash to the current thread
module RequestStore
  def self.store
    Thread.current[:request_store] ||= {}
  end
end

# middleware that initializes a request store and and adds a request ID to it
class Middleware::Instruments
  ...

  def call(env)
    RequestStore.store.clear
    RequestStore.store[:request_id] = SecureRandom.uuid
    @app.call(env)
  end
end

# class method that can extract a request ID and tag logging events with it
module Log
  def self.log(action, data={})
    data.merge!(request_id: RequestStore.store[:request_id])
    ...
  end
end