November 25th, 2014 by Josh

Log tagging in Rails

Sometimes when debugging issues in a live application, it can be hard to pair up log entries with application requests. The water can become even murkier when you've got many application processes accepting requests from multiple entry points (such as a load balancer).

One way of dealing with this is to tag each request with a unique ID, and use that ID to trace the request throughout its lifespan. Heroku has a great article on HTTP request IDs over here.

We needed to do this recently whilst deploying a large application to the Heroku platform, so we decided to look into log tags within Rails.

It's quite simple to get tags showing up in your Rails logs. Say we want to show the current request ID against each log entry, all we need to do is configure the log_tags setting in an initializer:

# config/initializers/log_tags.rb

My::Application.config.log_tags = [ :uuid ]

Now you can filter the log content by a particular request ID to see all output related to a single request (including any requests to assets if you are using Rails to serve static assets). Some services let you search for keywords in logs (such as PaperTrail) which can make this process easier.

For example, a controller request before tagging might look like this:

Started GET "/dashboard" for 127.0.0.1 at 2014-11-24 15:48:30 +0000

And after:

[a00c54e0-874f-4358-a7b9-accef0c407c6] Started GET "/dashboard" for 127.0.0.1 at 2014-11-24 15:48:30 +0000

This is particularly useful on Heroku, as they set X-Request-ID at the routing layer, meaning we can trace the request from the very start when the request gets accepted by the router (before it hits any of your application dynos).

It's worth noting that if X-Request-ID is not set, Rails will generate a unique ID for the request itself, meaning you can still use this feature.

As well as :uuid there are many other symbols you can use to provide more useful tags in your logs such as :host and :remote_ip. You can also provide a lambda/proc as an item in the settings array should you need to define more custom behaviour.