Debugging is an important skill to develop as you work your way up to more complex projects. Seasoned engineers have a sixth sense for squashing bugs and have built up an impressive collection of tools that help them diagnose and fix bugs.

I'm a member of Heroku’s Ruby team and creator of CodeTriage and today we’ll look at the tools that I used on a journey to fix a gnarly bug in Sprockets. Sprockets is an asset packaging system written in Ruby that lies at the heart of Rails’ asset processing pipeline.

At the end of the post, you will know how Sprockets works and how to debug in Ruby.

Unexpected Behavior in Sprockets

Sprockets gives developers a convenient way to compile, minify, and serve JavaScript and CSS files. Its extensible preprocessor pipeline has support for languages like CoffeeScript, SaaS, and SCSS. It is included in Rails via the sprockets-rails gem but can also be used in a standalone fashion, for example, to package Sinatra assets.

Earlier this month, we recorded a live-debugging session where we experienced particularly curious issue in Sprockets. We noticed that the bug broke the critical asset precompilation rake task, but only if the name of the project folder was changed between successive task executions. While project folder renames might seem relatively uncommon, they happen frequently on Heroku because each build happens in a unique directory name.

While this bug itself is interesting, what’s even more interesting is learning from our debugging process. You can learn about the tools and steps we use to narrow down the root cause, and ultimately fix the bug.

If you’d like to watch the full debugging session, check out the video or just follow along by reading the text below. We’ll walk through a debug workflow and find the root cause of this bug.

A Guide to Debugging in Ruby

Head-scratching, non-obvious bugs are worth investigating because they may lead to other unnoticed or unreported bugs.

Thankfully, Ruby comes with some powerful debugging tools that are easy to use for beginners. For a nice overview, check out this Ruby debugging guide that covers basics like the difference between p and puts and also discusses a few of the interactive debuggers that are available in the Ruby ecosystem. For the rest of this post, however, you won’t need to know anything more advanced than puts.

Reproducing the Bug

The best way to learn debugging is just to dive in and try it. Let’s set up Sprockets in a local environment.

Clone CodeTriage

We need a Rails app to reproduce this bug so we’ll use an open source example. I am the creator of CodeTriage so it’s natural to use that application to demonstrate the problem, although you can reproduce it with any Rails app that uses Sprockets. CodeTriage has helped developers triage issues for thousands of open-source projects.

First, clone the CodeTriage repository, install dependencies, then switch to a branch that contains the code we need to reproduce the bug. A working Ruby environment is assumed.

$ git clone git@github.com:codetriage/codetriage
$ cd codetriage

$ gem install bundler
$ bundle install

$ cp config/database.example.yml config/database.yml
$ git checkout 52d57d13

Compile the Assets with Rake

Next, execute the following steps to make the bug show up in our local environment.

$ rm -rf tmp/cache
$ rm -rf public/assets

Next, run the rake task for precompiling assets, which should succeed:

$ RAILS_ENV=production RAILS_SERVE_STATIC_FILES=1 RAILS_LOG_TO_STDOUT=1 bin/rake assets:precompile

Rename the Project Folder

Now, change the name of the project directory by copying its files into a new directory called codetriage-after and deleting the old codetriage directory.

$ cd ..
$ cp -r codetriage codetriage-after
$ rm -rf codetriage
$ cd codetriage-after

One more time, run the assets:precompile rake task:

$ RAILS_ENV=production RAILS_SERVE_STATIC_FILES=1 RAILS_LOG_TO_STDOUT=1 bin/rake assets:precompile

The task should fail this time and produce the following error message:

Sprockets is complaining that it can’t find the file /private/tmp/repro/codetriage/app/assets/javascripts/application.js.erb.

This actually makes sense because in the last step we changed codetriage to codetriage-after as our project folder name, yet it is looking in codetriage.

(Note that the /private/tmp/repro part of the path may be different for you based on where you cloned the codetriage repository.)

Finding the Root Cause of the Bug

Now that we have reproduced the bug in the video, the next step is to jump into the code of the Sprockets dependency at one of the lines in the stack trace in a method called fetch_asset_from_dependency_cache. Your application depends on reading code in the libraries, which is required when debugging, especially once you have ruled out any issues with the code you’ve written.

Read gem code with bundle open

Ruby’s de-facto gem manager Bundler contains a helpful command called bundle open that opens the source code of a gem in your favorite editor. Run it like this:

$ bundle open sprockets

As long as you have a $EDITOR or $BUNDLER_EDITOR environment variable set, your preferred code editor will open to the project directory of the specified gem.

Now you can browse the gem source code and even modify it, adding print statements to see the value of variables or trying out various fixes to see if they work.

How Sprockets Caches Files

The error message above implied that the wrong value is being stored in the Sprockets cache, so the next step is to look at the cache to confirm. The cache is stored on disk across many files, so first we need to find the specific file that contains the record we want to inspect. The key to that record is a digest of the Sprockets cache ID. That’s the value we’ll try to find in the files.

Once you have the Sprockets code open, navigate to lib/sprockets/loader.rb, where you’ll find the method fetch_asset_from_dependency_cache toward the end. The documentation for this method provides insight into how Sprockets uses the idea of pipelines, histories, and dependencies to aid in caching. To get more of the backstory, I recommend watching the video starting from about the six-minute mark.

We examined the on-disk contents of the Sprockets cache, looking for the ID cache key of a specific object in the Sprockets cache.

$ grep -R 5d0abb0a8654a1f03d6b27 tmp/cache

This is a helpful debugging command to file away for later. grep -R searches through the tmp/cache directory looking for any files that contain the string “5d0abb0a8654a1f03d6b27”, which is a Sprockets cache key. The -R flag is what makes it traverse directories recursively.

In our case, the grep command does produce a cache file and we can use cat to view the contents. Inside of that cache file, we find something unexpected: an absolute path to an asset. Sprockets should only cache relative paths, not absolute paths. Since we changed the absolute path to our project directory to create this bug, it’s quite likely that this is the culprit.

Loading Up IRB

To investigate further and confirm this suspicion, we fire up IRB, the interactive Ruby debugger. If you’re new to Ruby or the IRB, we recommend How To Use IRB to Explore Ruby as a good way to see how to use it. It’s simple but powerful and is a must-have in your Ruby debugging toolkit.

We then use IRB to inspect the file cache from Sprockets point of view.

$ irb
reirb(main):001:0> require ‘sprockets’
reirb(main):001:0> Sprockets::Environment.new.cache
reirb(main):001:0> Sprockets::Environment.new.cache.get(“5d0abb0a8654a1f03d6b27”)

Unfortunately, this does not work because the cache key is not the same as the cache ID. So, we move on to confirming this hypothesis in another way. We still include this example here to let you know that IRB is something you can use for any Ruby code and specifically with the handy Environment class in Sprockets.

Fixing to_load and to_link

To fix the bug, let’s modify the to_load and to_link methods in loader.rb to force relative paths for objects going into the cache and coming out, using the compress_from_root and expand_from_root utility methods from Sprockets base.rb. This ensures that absolute paths won’t make their way into the cache again, and consequently, that renaming the project directory won’t cause any issues in subsequent asset compilations.

if cached_asset[:metadata][:to_load] && !cached_asset[:metadata][:to_load].empty?
  cached_asset[:metadata][:to_load] = cached_asset[:metadata][:to_load].dup
  cached_asset[:metadata][:to_load].map! { |uri| compress_from_root(uri) }
end

 if cached_asset[:metadata][:to_link] && !cached_asset[:metadata][:to_link].empty?
  cached_asset[:metadata][:to_link] = cached_asset[:metadata][:to_link].dup
  cached_asset[:metadata][:to_link].map! { |uri| compress_from_root(uri) }
end

Our pull request to fix the bug contains a test to prove that the fix works. Writing tests for your bug fixes is a best practice that you should always strive to follow. It’s the best way to prevent old bugs from crawling back into your codebase.

Wrap-up

Inevitably, your code will do something that couldn’t possibly happen. That’s when you need to get out your debugging tools. We hope that you have picked up a few new ones from this post.

Your code will do something that couldn’t possibly happen in production. If your app runs on Heroku, make sure to familiarize yourself with the variety of logging solutions available as add-ons. These add-ons will make running and debugging problems on Heroku easier and they only take seconds to set up.