Optimizing Ruby Logging for Faster Debugging and Problem-Solving

Share this article

This article was sponsored by Loggly. Thank you for supporting the sponsors who make SitePoint possible.

In English, words that end with the ‘-ly’ suffix are usually classified as adverbs. Adverbs, for the grammatically challenged (and many of us devs are), modify verbs. Here are some examples with the adverbs bolded:

  • Jezebel runs quickly. (meaning, very fast)
  • The comment troll hides behind the anonymity of the internet stealthily. (meaning, like a wimp or in an undetectable manner)

Regardless of your feelings toward comment trolls, I hope these examples give you a basic understanding of the English adverb. This understanding is pertinent, as I am proposing the creation of a new adverb:

Loggly: adv. , recorded in a complete and extensible way. The prudent developer deployed the application loggly.”

I do not take this recommendation lightly. While any language is a living, breathing thing, adding new terms should be done only when a concept is found to be underrepresented in the existing idiom. After trying out the service offered by Loggly, I feel like such a concept has been found.

In this article I’m going to look at Loggly from the perspective of a Rubyist, explaining how to set up Loggly by adding it to my Leaderboards example. If you’ve read that article, then you know the Leaderboard is a simple Rails app hosted on Heroku. It does have some JavaScript behavior, which will allow me to show some client-side logging.

But first, let’s look at why you’d want to log in the first place, before moving into setting it up for our purposes.

Why Log?

For years, one of the many items omitted from most applications was an effective logging strategy. In most cases, logging offers the developer the only look into an application at runtime. Effective log usage and monitoring can help you predict an application’s future, allowing a proactive approach to maintenance as opposed to reactive.

However, when there’s a time crunch, the focus is about features, not logging. Logging and testing are two items you have to be disciplined about during development. Otherwise, your production experience is likely to go poorly.

Once you’ve accepted the need to log, there’s a new problem. Most applications have tons of moving parts: the operating system, web server, application, database, background jobs… just to name a few. All of these parts have one or more processes to log, and we haven’t even talked about clustering yet. How do you manage all the logs when you need to see behind the production curtain? Loggly can help with easy and extensible log search, an intuitive UI, agent-free deployment (I think that’s the best part) and a pay-as-you-go model.

Setting Up

Head over to Loggly and sign up for a free account. The various setup pages are handily made available once you log in and use your Loggly account’s subdomain (user.loggly.com), so you can follow along with my setup below.

logglyruby1 - loggly homepage

When you land on the Source Setup page, you can easily see how to set up Loggly for operating systems, server-side apps, and client-side apps. I’ll run through setting it up with Rails and Angular, with the aim of adding Loggly to my Leaderboards example that I mentioned above. I’ve created a branch on the app repository for these changes here.

Server-side

When it comes to using Loggly with Rails, you have a couple of options. The first one is to configure syslog to use Loggly, then use the syslogger gem in your app. The second is to use the logglier gem, which I decided to do.

Configuring the logglier gem is standard Rails stuff: 1) put configuration info into an initializer, 2) log as you normally would.

Gemfile

gem ‘logglier’

(Don’t forget to bundle)

config/initializers/loggly.rb

loggly = Logglier.new(<a href="https://logs-01.loggly.com/inputs/3e8f8c6f-2161-4544-8c04-bc134ac82590/tag/rails">https://logs-01.loggly.com/inputs/3e8f8c6f-2161-4544-8c04-bc134ac82590/tag/rails</a>, threaded: true, format: :json) <br />
Rails.logger.extend(ActiveSupport::Logger.broadcast(loggly))

Man, that configuration was done quickly , but not hurriedly. FYI, this will only work in Rails 4, as it added the ability to broadcast logs to multiple loggers. If you are on Rails 3, check out this post.

Time to write to the Rails log, just like we would if we weren’t using Loggly:

app/controllers/leaderboards_controller.rb

class LeaderboardsController < ApplicationController
  before_action :query_options

  def show
    Rails.logger.info("Showing a leaderboard")
    ...rest of file...

Seriously, could this be any easier?

Because I like to inform you completely, note that the above configuration will send ALL Rails logs to Loggly. This means all the template renders and everything else Rails barfs chattily into its logs. If you don’t like this, you could wisely include something like lograge to quiet things down a bit. I’ll show some examples later.

Client-side

How many of your applications are logging from the client? Do you have your javascript sending log events? How about your iOS or Android apps? I’d safely bet that most of us aren’t logging from the client nearly enough.

Fortunately, there’s a community-created, open source Angular module for Loggly called (uncreatively enough) angular-loggly. Most of the configuration of this is boilerplate Angular stuff, once you include the source in your asset pipeline.

application.js

//= require angular/angular
//= require angular-loggly/logglyService.min # I added this
//= require_tree

Note that, if you don’t use the .min file, you’ll need to pull in the Loggly javascript separately.

leaderboards.js.erb

var App = angular.module('App', ['loggly'])
.run(function(loggly) {
    loggly.setApiKey('3e8f8c6f-2161-4544-8c04-bc134ac82590');
})
...existing angular code...

Again, most of what I needed is Angular bootstrapping. I include the Loggly module in my application dependencies, then configure the API key in the run function, which is run once per page load.

Now, it’s simply a matter of logging using the Loggly service. Here is how I changed the entryForm directive, which handles the editing of a single leaderboard entry when the user double-clicks on the score:

.directive('entryForm', function (loggly){ // Inject loggly service
  return {
    restrict: 'E',
    scope: {
      entry: '=entry'
    },
    templateUrl: "<%=asset_path 'templates/entry_form.html'%>",
    link: function(scope, elem, attrs) {
      var input = elem.find('input'),
          form = elem.find('form');
      scope.editing = false;

      elem.bind('dblclick', function(){
        loggly.info("Editing started"); // Call loggly
        scope.editing = true;
        input.select();
        scope.$apply();
      });

      input.bind('keydown', function(e) {
        switch(e.which) {
          case 13: //Enter
            form.submit();
          case 27: //Esc
            loggly.info("Editing Cancelled") // Call loggly
            scope.editing = false;
        }
        scope.$apply();
      });
    }
  };
})

And there is client-side logging handled deftly. Rockin’.

Infrastructure – Heroku

The last bit of demonstration I’ll have for you today is configuring Loggly as a log drain for Heroku. As with most things Heroku, it’s easy:

$> heroku drains:add https://logs-01.loggly.com/bulk/<your loggly token>/tag/heroku --ap <your heroku app name>

Successfully added drain https://logs-01.loggly.com/bulk/<your loggly token>/tag/heroku
updating...done. Updated to 3.30.3

Notice, it’s simply using the Loggly HTTP/S Bulk Event Endpoint, which, awesomely , enables both single and bulk event handling. Basically, just configure any app to POST to http://logs-01.loggly.com/inputs//tag/http/, like so:

curl -H "content-type:text/plain" -d '{ "message" : "hello" }' http://logs-01.loggly.com/inputs/<token>/tag/http/

And you’re done. The bulk endpoint allows the sending of 5MB per batch.

Between HTTP/S and File Monitoring (another feature we’ve unfortunately omitted in this article), there is absolutely nothing that cannot be logged. Nothing. Feel free to spend your time unwisely trying to come up with one.

Loggly in Action

It’s difficult to know when and how you’ll need a logging solution before putting the app into production. Applications simply don’t behave the same way in production as they do in development. Here I’ll go through a few examples from my own use of the Leaderboard app I mentioned earlier.

To recap, this is a Rails app consisting of a simple leaderboard, able to accept a name and a score for a new entry, return a JSON representation with the supplied name, support HTML and JSON representation of all the entries on the leaderboard, not allow more than 100 records to be returned for a single request, and allow for the removal of the specified name from the leaderboard. I used redis and the leaderboard gem from Github user agoragames.

Here’s a screenshot of what I came up with, but follow the link above for the full story.

logglyruby2 - leaderboard

Now let’s take a look at how Loggly thankfully helped me sort out my Leaderboard logging woes.

Log Errors

Loggly has skillfully put together a web-based user interface that is both intuitive and extensible. Once you have some events defined, click on the “Dashboards” tab at the top of your Loggly page and behold something like this:

logglyruby3 - dashboard

The Dashboard serves up an “All Events” bar graph for the last hour. It’s easily changed to the last 24 hours with a click. There’s also “Saved Searches”, “Alerts”, and “Top Values”. This is the default dashboard, but you can add your own with a simple click of the “+ New” link on the tab bar.

With this powerful UI up my sleeve, and playing around with the Leaderboard app’s features, I noticed I would get errors in the logs for some POSTs to /entries:

2015-04-12 13:30:10.837 UTC at=info method=POST path="/entries/" host=ccleader.herokuapp.com request_id=0e02eb90-f4bc-4e30-b5c9-7773d8dc3517 fwd="75.190.154.129" dyno=web.1 connect=1ms service=63ms status=404 bytes=1804
2015-04-12 13:27:25.863 UTC at=info method=POST path="/entries/" host=ccleader.herokuapp.com request_id=98e34aee-c08d-4b5c-b8d9-fc495293a12ffwd="75.190.154.129" dyno=web.1 connect=0ms service=10ms status=404 bytes=1804

There was no other info.

Fortunately, Loggly’s Search tab allows you to enter a search term or tag, specify a date range (crucial when looking through logs), favorite searches, or create alerts from a search. The searches are full-text enabled, as well, so you can really pinpoint an entry when needed.

There are drill-down capabilities based around items like the aforementioned tags, hosts, priority, etc. Now, you can simply click through to isolate your search as quickly as you like.

Searching for these 404s: there were many. Loggly also has a very handy “View Surrounding Events” button when selecting a log entry that displays the events around the selected event. When I clicked that, it showed:

logglyruby4 - surrounding events

So, some of the deletes for the entries were failing. But why? I couldn’t reproduce it. In a usual Rails/ActiveRecord application, there would be an id parameter associated with the request. Here, we’re using the name, which is missing from the request above. The request should look like:

Started DELETE "/entries/Catherine%20Lynch%20MD"

but it looks like

Started DELETE "/entries/"

There must be an empty string key on our leaderboard. Looks like we need some validation… (which I’ll happily leave as an exercise for the user.)

Tracking a Request

Here’s another potential application for logging: tracking a request through all of the pieces it travels through during its lifetime (web server, application, service objects, etc.) The simple solution is to add a Request ID to the HTTP request and make Rails write it to the log. As this article on the Heroku blog explains, add:

config.log_tags =[:uuid]

… to config/application.rb or config/environments/production.rb. Now, when I find a bad request, I can grab that id, search for it in the Loggly UI, and get all the related log entries. From the above example, one of the 404s had a request id of d52588de-6aee-42d5-b223-3e2586388d61. Searching for that in the Loggly UI, I get back the Rails and router log entries.

2015-04-12 16:49:27.361 UTC at=info method=POST path="/entries/" host=ccleader.herokuapp.com request_id=d52588de-6aee-42d5-b223-3e2586388d61 fwd="75.190.154.129" dyno=web.1 connect=5ms service=73ms status=404 bytes=1804
2015-04-12 16:49:27.299 UTC [d52588de-6aee-42d5-b223-3e2586388d61] Started DELETE "/entries/" for 75.190.154.129 at 2015-04-12 16:49:27 +0000

You can see the UUID tag added to the Rails entry above. This can be extremely useful when combined with the Loggly UI.

logglyruby5 - uuid tag

Wrap Up

Logging effectively is a required pillar in any serious application these days. Developers can no longer afford to push logging to the side without seriously endangering the production health of their application.

Loggly offers a very compelling, easy-to-configure, easy-to-use solution to ensuring logging is handled so that you can focus on your application. Give it a try, I know you’ll be as impressed as I am.

While you’re doing that, I’ll be contacting Websters about adding my new adverb…

Glenn GoodrichGlenn Goodrich
View Author

Glenn works for Skookum Digital Works by day and manages the SitePoint Ruby channel at night. He likes to pretend he has a secret identity, but can't come up with a good superhero name. He's settling for "Roob", for now.

leaderboardlogglyrailsrubysponsored
Share this article
Read Next
Get the freshest news and resources for developers, designers and digital creators in your inbox each week