Getting Started with Rails + Honeycomb

We hear you’ve got a Rails application you’d like to learn more about! Webapps like yours run the Internet, and we’re here to help you use Honeycomb to observe your Rails application. This guide will use the RailsBridge Bridge Troll application as an example (code here and site here), but you’re welcome to follow along in your own application instead.

Here are some example questions that this guide will aim to help you answer:

By the end of this guide, if you’ve followed along (and you should!), we should have:

Many thanks to the fine folks of RailsBridge for producing such a high-quality public Rails app for the community to learn from!

Preface: What has been staring us in the face already?

If you’re a Rails developer, you already know how wonderful Rails is for getting things to Just Work. And if you’ve spent any time looking at the default server output, you know how many timers are embedded in Rails itself— and how much useful information gets output to the (unstructured—what a shame!) server logs.

Example Rails log output

As you read through this guide, consider the following: What other sorts of data do you see in development all the time that might be helpful for debugging your application in production?

First up: Explore traffic patterns across controllers and actions

If you’re using Rails 3.0 or above, you can use the Instrumentation API to slurp all of this great metadata right into Honeycomb! Active Support Instrumentation is pretty great— it’s a part of core Rails that can help easily measure certain actions that occur from within Ruby code.

The Rails team built some instrumentation “hooks” into Rails itself, so that developers can be notified when certain events happen inside their application. We’ll take advantage of some of these to capture events about what your Rails app is doing, and to forward them on to Honeycomb!

The hook we’ll start with will be process_action.action_controller. This captures a whole bunch of useful metadata each time a controller in your Rails app handles an action:

{
  controller: "PostsController", # The Rails controller name
  action: "index",               # The Rails action
  params: {"action" => "index", "controller" => "posts"},     # Hash of request parameters
  headers: #<ActionDispatch::Http::Headers:0x0055a67a519b88>, # Request headers
  format: :html,                 # html/js/json/xml etc
  method: "GET",                 # HTTP request verb
  path: "/posts",                # Request path
  status: 200,                   # HTTP status code
  view_runtime: 46.848,          # Amount spent in view in ms
  db_runtime: 0.157              # Amount spent executing database queries in ms
}

This default set of metadata is great to start with: we’ll be able to isolate specific controllers, actions, and formats; track successes and failures via HTTP status code; and drill down into how much time we’re spending in the database. Cool!

Active Support expects us to start off by subscribe-ing to a particular event type, so we’ll do just that. Add an initializer (we’ve named ours config/initializers/honeycomb.rb), pick out the bits we’re interested in, and send it off to Honeycomb.

# config/initializers/honeycomb.rb

require 'libhoney'

$honeycomb = Libhoney::Client.new(:writekey => "YOUR_WRITE_KEY",
                                  :dataset  => "rails")

ActiveSupport::Notifications.subscribe /process_action.action_controller/ do |*args|
  event = ActiveSupport::Notifications::Event.new(*args)

  # These are the keys we're interested in! Skipping noisy keys (:headers, :params) for now.
  data = event.payload.slice(:controller, :action, :method, :path, :format,
                             :status, :db_runtime, :view_runtime)

  # Massage data to return "all" as the :format if not set
  if !data[:format] || data[:format] == "format:*/*"
    data[:format] = "all"
  end

  # Pull top-level attributes off of the ActiveSupport Event.
  data[:duration_ms] = event.duration

  $honeycomb.send_now(data)
end

In this code snippet, we start off by registering a subscriber to the events we’re interested in (here, we’re interested in Instrumentation events that match process_action.action_controller) so that our code is set up to consume those events as they happen.

Note: Active Support gives us a lot of stuff on the payload—in the code above, we’re choosing just a subset of keys to start with. In particular, :headers and :params contain a lot of potentially interesting values, as well as a lot of potentially uninteresting ones.

To familiarize ourselves more easily with what Rails sends Honeycomb, we’re skipping those two keys. Once you’ve completed this guide, we’d recommend coming back and seeing whether there’s anything underneath :headers or :params that might be particularly interesting.

Finally, we call #send_now on our Libhoney::Client in order to send the entire payload off to Honeycomb’s servers.

Note that libhoney does all of its HTTP transmission on a background thread, so you can trust #send_now to have minimal impact on your application’s performance.

After clicking around a bit in our local Bridge Troll application to trigger some HTTP requests, we can start seeing data in Honeycomb: below, we’re exploring which controllers and actions are being requested the most and how long those requests are taking.

Count and P95(duration_ms) of controller/action pairs

Next: Add some application-specific metadata via ApplicationController

ApplicationController already knows something about every request flowing through your application, which makes it a great place to start capturing some app-specific metadata— and ActionController::Instrumentation provides an overridable method, append_info_to_payload, that makes it simple to add data to the Instrumentation payload.

For our example, since Bridge Troll uses Devise for authentication, we can add information about the current user to our Instrumentation payload from right inside our ApplicationController.

# app/controllers/application_controller.rb

def append_info_to_payload(payload)
  super

  metadata = {}
  if current_user
    metadata[:current_user_id] = current_user.id
    metadata[:current_user_email] = current_user.email
    metadata[:current_user_admin] = current_user.try(:admin?) ? true : false
  end
  metadata[:flash_error] = flash[:error] if flash[:error]
  metadata[:flash_notice] = flash[:notice] if flash[:notice]

  # Attach to ActiveSupport::Instrumentation payload for consumption by
  # subscribers
  payload[:metadata] = metadata
end

Honeycomb Tip: In addition to any user information, we’re also capturing flash messages here if they exist! Who knows—they might be helpful if we ever have to debug an error or strange user interaction in the future. And adding fields like this won’t slow Honeycomb queries down, because Honeycomb’s query engine only pulls in the fields actively being queried over.

Breaking events down by flash_notice or flash_error can give you a unique insight into how your users have been experiencing your system.

Breaking events down by flash message can give you a unique insight into how your users experience your system

The payload argument for append_info_to_payload is the event.payload we’re cherry-picking data off of in our initializer— so, since we’re introducing this new :metadata key on the event payload, let’s make sure it gets passed along to Honeycomb as well:

# config/initializers/honeycomb.rb

ActiveSupport::Notifications.subscribe /process_action.action_controller/ do |*args|
  # ...
  # Keep the existing code in place, where we're pulling standard
  # fields off of the event.payload
  # ...
  
  # But add this: merge in anything we added in the hash referenced
  # by the :metadata key
  data = data.merge(event.payload[:metadata])

  # And send as usual :)
  $honeycomb.send_now(data)
end

Cool! Now that we’re populating a hash of useful event metadata in our ApplicationController and merging it into our Honeycomb payload inside the initializer, we’re able to start analyzing individual users’ Rails requests from inside Honeycomb! We can figure out which users are triggering the slowest requests, or even just see traffic patterns with a given email address.

Honeycomb Tip: Capturing user information in events is a classic example of a “high cardinality” field— meaning, there are tons of possible unique values for the field.

Including user IDs or email addresses can sometimes cause problems in other data systems— but Honeycomb makes it easy to filter your app’s requests by a given email address while also answering high-level questions (e.g. “Which endpoints are the slowest for this particular user?”).

Capturing user metadata makes it trivial to filter down to a single user’s traffic:

Zoom into a single user's traffic trivially

Finally: Capturing useful information in individual controllers

The standard Rails Instrumentation API, along with some application-level metadata, has gotten us pretty far— we can answer questions around user behavior, performance anomalies, etc— but if we want to really understand the detailed interactions in our application, we’ll want the ability to capture things specific to individual controllers.

Add useful fields for the (most of the) whole controller

The simplest way to capture controller-specific metadata is to do what we did in our ApplicationController: override append_info_to_payload for anything we want to add on the whole controller.

Here, we’ll focus on instrumenting a classic Rails controller, Bridge Troll’s ChaptersController, which manages listing, displaying, updating, and (sometimes) destroying RailsBridge chapters. Most actions on this controller work with a single @chapter instance variable, so it’ll be helpful to track which chapter we’re operating on.

# app/controllers/chapters_controller.rb

def append_info_to_payload(payload)
  super

  payload[:metadata][:chapter_id] = @chapter.id if @chapter
end

Note: The Rails convention of using a common instance variable name helps make sure that this code works nicely across multiple actions in the controller!

Add useful fields for one important action on a controller

There are often specific things in specific actions that are worth tracking. In our ChaptersController#index, for example, it might be interesting to know how many chapters are being returned to the user.

# app/controllers/chapters_controller.rb
def index
  skip_authorization
  @chapters = Chapter.all.includes(:organization)
  # Add this line:
  @honeycomb_metadata[:num_chapters] = @chapters.size
end

Honeycomb Tip: This is an example of a field that contributes to “sparse data”: sometimes not all fields exist on all payloads in a Honeycomb dataset, and that’s okay! Honeycomb handles these extra fields with grace, ignoring them if applicable (e.g. if you’re calculating the AVG(num_chapters), the query engine will ignore Honeycomb events without a num_chapters value set.).

Note that we’re working with something new here—there’s no payload to happily toss things onto. There’s no append_info_to_payload that we can invoke on a per-action basis, so we’ll have to figure out some other way to get metadata from inside this action onto the Instrumentation event’s payload.

We can use an instance variable (@honeycomb_metadata, here), but let’s first make sure that variable exists. To do that, we can add this to a before_action on our ApplicationController:

# app/controllers/application_controller.rb
before_action do
  # Add this line to initialize Honeycomb instance variable
  @honeycomb_metadata = {}
  # ... Keep this existing logic
  if current_user.try(:admin?)
    Rack::MiniProfiler.authorize_request
  end
end

We’ve already added code to ChaptersController to populate that hash, so let’s go ahead and make sure that our metadata hash gets handed to the Instrumentation payload. Instead of just initializing metadata = {} like we did in the previous section, let’s initialize it to whatever @honeycomb_metadata contains.

def append_info_to_payload(payload)
  super

  metadata = @honeycomb_metadata

  # ... Continue on with the if current_user check and payload[:metadata] assignment
end

Now, when everything is saved and we reload ChaptersController#index, the page loads and… our Honeycomb dataset now knows about num_events on requests for this controller and action!

If we take this one step further and even add num_events, to track the number of events returned for a given Chapter in ChaptersController#show:

# app/controllers/chapters_controller.rb
def show
  skip_authorization
  @chapter_events = (
    @chapter.events.includes(:organizers, :location).published_or_visible_to(current_user) + @chapter.external_events
  ).sort_by(&:ends_at)
  @honeycomb_metadata[:num_events] = @chapter_events.size
  # ... Keep on keepin' on
end

Then (see the video below!) we can start with a graph of the COUNT and AVERAGE(num_events) of requests going to individual controller/actions, then adjust the query to break down by chapter_id instead (including only the controller/actions that contribute towards num_events). This lets us iterate on how we want to break down our app’s traffic, while always making sure we have access to the raw events.

Next Steps

Now that we’ve instrumented the basics of our Rails application to send to Honeycomb, you’ve got all the tools you need to customize your own observability solution!

Let’s take a look at the changes we made in this guide. Our full fork of the Bridge Troll app can be found on GitHub.

Some suggested next steps:

Bonus: If you’re not on Rails

If you’re looking for a Ruby-based solution but aren’t on Rails, we’ve still got you covered! This approach of mapping individual requests to Honeycomb events is also useful for folks to get started with analyzing their system.

Our Rack middleware (available via gem install honeycomb-rack) captures a number of the same things that process_action.action_controller captures: request path, request duration, and status code. It’s a little bit more involved to add custom metadata like we did in the last section, but it’s certainly still possible :)

# config/application.rb
require 'rack/honey'

class Application < Rails::Application
  config.middleware.use Rack::Honey::Middleware, writekey: "<YOUR WRITEKEY HERE>", dataset: "<YOUR DATASET NAME HERE>"
end

Bonus: Understanding ActiveRecord performance

To go beyond just controller activity, Rails also exposes sql.active_record events to describe how your application is interacting with the database. The API is even nice enough to normalize the SQL queries for you, separating out the shape of the query (SELECT * FROM users WHERE users.id = ? from the parameters ["id", 1]).

To add this to our existing initializer, let’s be a little bit more careful about where we’re sending our data. Our process_action.action_controller events are currently going to a "rails" dataset in Honeycomb. Let’s make sure these ActiveRecord events are sent to a "active_record" dataset instead.

Honeycomb Tip: We recommend separating events into different Datasets when two events aren’t comparable in their frequency or their scope.

In the "rails" dataset, one inbound HTTP request maps to a Honeycomb event—this makes that dataset easy to reason about and analyze. Because a single Rails request may trigger many ActiveRecord operations, and because ActiveRecord operations have little in common with the controller or action that invoked them, it feels more natural to keep them in separate datasets.

Otherwise, the process should generally look the same: pull data off of the ActiveSupport::Notifications event, do any necessary cleanup on the data, and send it on up to Honeycomb:

# config/initializers/honeycomb_notifications.rb

ActiveSupport::Notifications.subscribe /sql.active_record/ do |*args|
  event = ActiveSupport::Notifications::Event.new(*args)
  data = event.payload.slice(:name, :connection_id)
  data[:sql] = event.payload[:sql].strip
  event.payload[:binds].each do |b|
    data["bind_#{ b.name }".to_sym] = b.value
  end
  data[:duration] = event.duration

  data[:local_stack] = caller.select{|e| e.include?(Rails.root.to_s)}

  $honeycomb.send_now(data)
end

There are a number of different things we can do with the bind parameters on a given ActiveRecord call. Here, we’re actually sending each bind parameter in as a separate field on a Honeycomb event. If this significantly increases our set of defined columns, you can define a whitelist of bind variables worth tracking or send the serialized map of bind names/values as an opaque, human-readable blob.

Under the :local_stack key, we’re capturing the file and line number that triggered the ActiveRecord call— so we should be able to pinpoint the exact origin of a particularly expensive or suspicious database operation.