The first and most widely used method of debugging Ruby applications is simply outputting text data. Let’s look at a few approaches at increasing levels of expertise.
Reading a Request/Response
Greatly undervalued by newer Rails developers, the first step when observing unexpected behavior should be the server log and the request/response information. Let’s pick apart an example.
Here’s an actual request from a sample application:
Here are some of the facts we can learn from reading the request:
- Line1: It executed a
/productswhich should trigger the
ProductsController. Is this the controller and action intended? Especially scrutinize the request verb, this is a common place for mixups.
- Line2: It did attempt to execute
- Line3: The params hash. Look for elements that are blank/nil. Is the structure reasonable? Unfortunately, because of the UTF-8 checkmark, this hash can’t be copy/pasted into the console for testing unless you’re on Ruby 1.9.2. If you have trouble navigating this hash:
- Copy it from the log output
- Paste it into a text editor
- Remove the
- Copy the result
- Paste it into console and experiment
- Inspect whether attributes are correctly nested, correctly named, etc
- Lines 4-6: See the SQL interactions. Particularly pay attention to
INSERTstatements. Is the information from the Line 3 params in the
INSERTor are there a bunch of
nilfields? The most common issue you’ll spot here is this:
text WARNING: Can't mass-assign protected attributes: [your attributes here]In that case, look in the model for the
attr_accessiblemethod call and see if additional fields should be made accessible. Note that the suffix matters, so making
productaccessible will not automatically accept
product_id, list both to allow mass-assignment via ID number or actual object.
- Last Lines: Redirect or render and HTML status code. Usually not helpful unless the app is redirecting you somewhere unexpected.
Just to say it one more time, the issue about Can’t mass-assign protected attributes is an incredibly common issue new Rails developers spend hours debugging. If you see the error in the log, though, it can be fixed in seconds. Just go to your model file and add the attributes to
Let’s next look at adding temporary instructions to our application.
Looking at the server log gave lots of great info, but it doesn’t help with inspecting the values of variables or instructions. For that job, use the
warn method of Ruby’s
Kernel object. Here’s how you might insert it into the
create action used above:
1 2 3 4 5 6 7 8 9 10
Then in the output log see the results:
Notice that the warn comes out before where the log claims it is "starting" the response. The
warn is output immediately, while the normal logging operations are buffered and output all together.
When I use warn I’ll typically put in some label to the output, like the
Product before save here. The messages for
warn are just strings, so you can use
\n newlines or other text formatting to make them easier to read.
One of my most frequently used techniques is to intentionally raise an exception. If I wanted to check out the
@product object during the
create action and maybe look at the parameters of the request, I’d typically do this:
1 2 3 4 5
raise will immediately halt execution and display Rails’ normal error page. The
raise method accepts one parameter, a string, which will be output as the error message.
With this usage you’d see something like this:
The first line specifying that it was a general
RuntimeError exception and the second line is the message, the result of our
inspect is a better choice than
to_s as it’ll show more about the object’s internal state.
Also, further down the page you’ll see the request’s parameters formatted in a YAML debug block.
This is a great debugging technique when writing Rails applications because you don’t have to dig through anything – execution halts right at your message.
You can even use
raise in conjunction with Ruby’s here-doc and string interpolation to create a block of output:
1 2 3 4 5 6 7 8 9 10 11
If you can get to the point of execution where a view template is being rendered, then you can take advantage of the
debug helper method. It accepts one object as an argument and outputs a nicely formatted YAML representation of the object wrapped in
<pre> tags. The built-in Rails stylesheet already has styles for the
<pre> tags for this reason.
For instance, in the form used with the
create action, I could insert
debug like this:
Then when the view is rendered the YAML output will be visible.
But there’s a serious problem with adding debug code – it tends to get left behind and sent into production! One solution I’ve used is to define this helper in
1 2 3
Then in the view templates just use it instead of the built-in
Now any debug code would be hidden in production. Want to take it a step further? How about this:
1 2 3 4 5 6 7
Now, assuming that you have coverage of your views in automated tests, debug code will get caught before hitting production!
A Custom Logger
Let’s say you want to debug a more complex process. Maybe it involves several "checkpoints" across multiple methods. Or you want to build an audit trail for actions in your application. You need a custom logger.
It’s very easy to create and use thanks to Rails
ActiveSupport::BufferedLogger. Imagine we want to build an audit log for our application. Start with an initializer
1 2 3 4 5 6 7
Then anywhere in your application call the
1 2 3 4 5
log/audit.log and you’ll find messages like this:
Tweak the formatting to your liking, then add auditing wherever needed in your application!
That’s great for development, but what about accessing our logs in production?
The first step is to enable Heroku’s "Expanded" logging add-on. From within your project directory, assuming it is already running on Heroku:
Getting logs from Heroku is simple:
Which will give you output like this:
The marker in
 corresponds to the dyno generating the message. The log aggregates information from all your dynos and workers, so it’s great for tracking down complex interactions between components.
For more extensive discussion, check out the Heroku resource center here: http://devcenter.heroku.com/articles/logging
Distributed Logging with Greylog2
That kind of approach works great for a single instance, but what about coordinating multiple machines or logging from non-Ruby processes? Then you need a distributed logging system.
I took a poll of Ruby developers and three options stood out:
- 3rd party logging services like Papertrail
- Open source with commercial support Syslog-ng
- Open source Graylog2
The third party services are definitely the easiest to work with, but you’re incurring extra costs and losing lots of control. If I were working on a small team and didn’t have dedicated DevOps staff, I’d definitely go this route.
Syslog-ng is probably the most powerful of the three, but it’s no fun to work with. The setup process was referred to as "black arts" by one developer. It requires installation on both the client and server sides, which is a lot of work. It’s a pure Unix solution that doesn’t leverage any Ruby.
Finally Graylog2 is quite interesting. You run a Java-based server backed by a MongoDB database, then submit log messages over UDP from a variety of client libraries. Because it relies on simple network protocols, the client-side setup is minimal. If logging every single entry is of critical importance and your server network experiences volatility, then the "fire and forget" nature of UDP is not going to be a good fit. But if you’re ok with the possibility of a very occassional slip, then Graylog2 is a solid choice.
Graylog2 Server Setup
The server setup on a Unix system is painless:
- Install and setup MongoDB if not already available (
brew install mongodbusing Homebrew for OS X)
- Download and decompress the server from https://github.com/Graylog2/graylog2-server
- Copy the
/etc/graylog2.confand edit with necessary MongoDB credentials. Also, changing the host from
127.0.0.1was necessary due to a Java quirk on OS X.
- Start the server with
java -jar graylog2-server.jar
Graylog2 as Rails Logger
With the server running, let’s try to use it for our normal Rails application logging instead of a
Install the Gem
Gemfile and add a dependency on
bundle to setup the dependency.
Configuring the Logger
config/application.rb and inside
class Application add:
Normal Rails logging uses terminal colorization which looks crazy when you send it to other services, so we turn the colors off.
config.logger changes the Rails logger to use an instance of
GELF::Logger. The instance needs:
- The ip of the Graylog2 server
- The port
- (Optionally) a "facility" name for categorizing messages from this server on the log server
Restart the Rails server and you’re good to go…maybe? How do we check out the results?
Graylog2 Web Interface
Graylog2 offers a Rails-based web interface to view, search, and manipulate the logs. If your machine is already setup with Ruby, then it’s easy to get the web interface going.
- Download the code from https://github.com/Graylog2/graylog2-web-interface
- Edit the
config/mongoid.ymlto connect to the MongoDB server on the Graylog2 server. Note that the web interface and logging server could run on different machines.
bundlefrom the project directory to setup dependencies
- Start the server in production mode:
rails server -e production
- Open the address in a browser and create a new user if one hasn’t been created already
- See your log entries pouring in!
Dealing with Exceptions
You probably don’t write bugs, but maybe someone else on your team does. Then they’re going to cause exceptions in the Rails app. The exceptions should get logged as part of the normal logging facility, but there’s also another approach.
Graylog2 offers a Rack middleware just for logging exceptions. From inside your Rack-based application:
- Add a dependency on
bundleto setup the gem
- For Rails, load the middleware by editing
config/application.rband adding this with the correct ip address:
- Or, for a Sinatra application:
Start your server, cause an exception, and see it pop up in the Graylog2 interface.
Want to log messages from a background job running through Resque or similar? No problem. Somewhere in the setup of your worker object, setup a
Logger object and define a convenience method for posting message:
1 2 3 4 5
audit whenever you want to record data. There are other options you can use to structure the data for GELF here: http://rdoc.info/github/Graylog2/gelf-rb/master/GELF/Notifier
Grab the Blogger sample project, create a branch, and try out each of the following techniques:
$ $ $ $
attr_accessible :titleto the
Articlemodel. Then create an article through the web interface. Check out the log file from your server and find the warnings, notice the
nildata in the
- With that
attr_accessiblestill in place, use
warnstatements in the
createaction to output the state of the
Articleobject after creation. Find the output in the server log.
- Now, instead of using
warn, try using
raise. Observe what happens when you call
raiseon the object itself. Then add
.inspectand trigger the
- Add a call to
show.html.erbto display the current article.
- Extra challenge: Write a
dhelper as described above. Add it to your application’s layout so every page displays
@articlesif they exist.
- Extra challenge: Write a
- Implement a custom logger and add log entries for each step of the article life-cycle:
destroy. Trigger a few of those actions and see that they’re output in the audit log.
Once complete, either commit (
git commit) or get rid of (
git reset --hard) your changes. You can stay on the debugging branch for the next section.