Debugging Header Image

Overview of Debugging Tools for Rails Application

   Back to list

It doesn’t matter how easy programming language is to use, it’s very likely that sooner or later we encounter some bugs in our code. Luckily, Rails provides many useful tools which can help us to deal with them.

In this post I’m going to look through four interesting debugging tools:

  1. Active Record Backtrace SQL Queries Plugin
  2. Logger
  3. Byebug
  4. Pry-Byebug

With help of Logger, Byebug, and Pry-Byebug, we will fix the same problem, so you don’t need to read the whole tutorial if you’re going to use just one. Using Active Record Backtrace Plugin is also worth seeing, additionally.

However, I will show you all of the different ways of usage for debugging things to allow you to discover your own preferences easier and show you the different ideas behind debugging.

General tips

Before focusing on real examples, here are some general tips that should be used before beginning any debugging.

1. Always read error messages.

Carefully reading error messages may give us essential information, which allows us to understand what a problem is, including: what class/method does the error reference, what is the class/type of the object, if object is nil, if you call a method on this class/type of object, or what lines of code should be investigated.

2. In the stack trace, pay close attention to the code lines that come from your project.

There are lines starting with app/… . In most cases, your own code generates a problem.

error

If you already know this, we move on to Rails debugging.

Ruby on Rails Debugging

Below is a page from an application that isn’t working correctly, and we’ll try to fix it. There is a list of clothes with prices, sizes, and categories that they belong to. The application must be able to lock the chosen size of clothes, which is not in the inventory.

pic1

Steps to lock a clothing size:

  1. Check the checkboxes in a row.
  2. Click the button “Lock sizes” in the same row.
  3. The last updated record should be shown in the top of the products list.

pic2

Problem to solve?

After clicking the “Lock sizes” button, the chosen clothing type (“Destroyed Drawstring Jeans”) is shown on the top of the list, but checkboxes are unchecked again. This means we made a mistake somewhere in our code and our record is not saved properly to the database. We’ll find out why by using cool Rails debugging tools.

Let’s dive into the code and see how this page works. Here is the view with the table containing the clothes.

Inside the body we render partial _product_list.html.erb

The code for locking clothing sizes is in the ProductsController.

lock method reads params, which we send using javascript lock_sizes() method by clicking on the button “Lock sizes”.

lock_sizes() method looks like this:

We pass the product_id to the method, look for checkboxes with class containing the sent product_id and create hash sizes with info about the locking sizes. Using console.log(sizes) in the lock_sizes() method we can see hash content:

pic3

advice1

After that, we send an ajax request to the lock method in the ProductsController with product id and previously created sizes hash. Then, in the controller lock method we update the locked_by_size field in the database for a product and re-render product_list with new products by sending the partial to the html element.

However, there aren’t any error messages. Therefore, we need to review logs.

When our server still is running in the console, we can get the following output:

pic4

What does logs tell us?

What kind of request did the server receive and which controller action was invoked? In our case, there is lock method in the ProductsController. We can see parameters sent to the method and many queries executed by the controller. Logs also inform us about ran scripts (lock.js.erb) and rendered views (partial view _product_list.html.erb).  

Active Record Backtrace SQL Queries Plugin

If the information about queries isn’t clean enough, we can use the active record-backtrace-sql-queries plugin. It’s helpful to track down where queries are being executed in application.

Add the module to lib/query_tracer.rb

Now we only need to require the module from the initializer. Add the code below to the config/lib/query_tracer.rb and restart the server.

In the console, we get additional logs sources of SQL queries. It helps to avoid going through your code looking for the location of a problem, and we are now able to see exactly where queries are performed.

pic5

At first glance the parameters are sent properly. So why we can’t save the record?

The Logger

A very useful Rails feature is the capability to save information to log files at runtime that you can use to output messages. However, it can be very difficult and time consuming to debug full error logs in the production environment when application logs are choked by many irrelevant messages.

Please note that in production mode, you need to specifically switch logging to debug in order to see detailed information. Luckily, we can easily configure logging. Rails has a separate log file for each runtime environment, and I will give you a few tips how to use it.

advice2

In the config/application.rb or any other environment file you can change the configuration for logging.

To specify a logger:

kod1

advice3

To set the log level:

kod2

Log messages are saved into the respective log files depending on log level, and only messages at that level or higher will be printed. The are six available log levels:

pic6

For example, as a developer, you will probably want to know the internal program state. In this case you should set the Logger to :debug level. However, in a production system, you should use :info.

To write a log message with an explicit level:

kod3

There is the configuration I used for our application:


We don’t really need to set the log level to :debug, because it’s set by default in all environments.

advice4

In the config/environment.rb add the code below:

When we run the server the output we get:

pic7

Logger’s level is set to :debug so all messages are printed. For instance, if we use :warn level only warning, error and fatal messages will be recorded, as they have an equal or higher level.

Logger provides a few cool features. One of them is setting the format of log messages.

Add formatter to the config/environment.rb

Now, after restarting the server and viewing the index page, we see formatted logs that give us additional information about time, date and a log level.

pic8

Let’s now use Logger in the ProductsController lock method!

So far, we only knew there  was something wrong with saving records to the database. A wise decision would be to check the state of the chosen product before and after an update. To do that, we won’t need to format logs, so for now we will comment it.

Add 4 and 6 lines to the lock method.

We can use logger.debug instead Rails.logger.debug because our class inherits it from ActiveRecord.

Inspect method is one of views that helps generate human-readable data from any object. Other ways to inspect the object are to_yaml and debug methods.

advice5

In the console, we see our added messages.

pic9

As you can see, there are differences in the locked_by size field type. We finally found the source of the bug! The problem is that we don’t convert string to symbol in the locked_sizes_hash. That’s why we can’t overwrite this data in the database. What we need to do now is add to_sym method in the lock method.

Change the lock method:

Run Rails console and update all product to the initial state:

pic10

Then restart the server and try to lock a product size in the browser. Now locked_by_size field type is the same as before and after update.

pic11

We see that the data has been saved correctly.

pic12
Congratulations! You found and fixed the bug!

You now know how Logger works. Let’s find out how to use another useful Rails debugging tool.

When your code is behaving in a way you don’t expect it to, it may take too much time printing to the console and looking for the source of the problem. If you want to overview inside of your code while it executes, a better choice would be using a debugger.

I’m going to show you two easy to use debuggers: Byebug and Pry-Byebug.

Debuggers offer many useful commands. Here are the most common kinds:

pic13

To get a list of commands, or information about a specific command, you can always use help in the console.

pict1

Byebug

Byebug is the default debugger in Rails >= 4.2.0. If you use a lower version to install byebug, use command, and then restart the server if it’s running.

gem install byebug

You can add byebug method anywhere in your code. The execution will stop there, and you will be dropped into a debug console.

Let’s add byebug to our lock method.

When you use lock method execution stopping at the point, the byebug will set, and you will be dropped into an interactive shell.

pic2

We start to check if the parameters passed to the lock method are permitted.

pict3

It returns false and indicates that there is something wrong. Use params to print all content.

pict4

Let’s try to find out what’s going on.

Byebug gives us the ability to inspect variables. When we write locked_sizes_hash in the console, we get a nil. Why? Because the line we assign the data to the variable isn’t executed yet.

The arrow points to the line of code which will be executed next.

Type next in the console and then use the locked_sizes_hash variable.

pict5

The arrow points to the line below it and we have an access to the hash content. We can also check the state of the @product variable before saving changes to the database, as we’ll set it before calling the lock method. We can run any Ruby code here, so let’s print only the locked_by_size field.

pict6

Before the update, data had an initial state. We can go into methods using the step command. It’s really useful when you run your own methods. That way, you can inspect the variables inside.

Type step and then run var args  to see arguments passed to the update method.

pict7

If you want to go back to the previous frame type up. By running the list method, we get information of where we currently are.

pict8

Use the next method again to update the @product and inspect the locked_by_size field that belongs to the @product.

pict9

Great! We found  the bug again by using Byebug debugger!

To stop debugging, just run quit command.

Pry-Byebug

The basic setup of Pry-Byebug is as simple as installing byebug.

Add gem ‘pry-byebug’ to the Gemfile and run bundle install in the console.

ruby_article

After successfully installing the gem, use binding.pry command in our lock method.

Then restart the server, if it’s still running. Execution will stop in the first statement after the command.

pict10

As you can see, Pry-Byebug compared with Byebug colors the syntax, but it’s almost the same.

First, we will check parameters sent to the lock method.

pict11

We get ‘false’ again. This time, we will try to set a breakpoint to stop the code execution at the desired location, instead of executing line by line using next method.

Type break [number]. The number indicates a number of a line. In this case it’s break 17.

pict12

Let’s inspect the locked_sizes_hash variable by typing it in the console. We get a nil because we still didn’t assign anything to the variable.

Run continue method.

pict13

As you can see, the execution was stopped in the 17 line, and we can now get the hash content.

The next step will be inspecting @product before call an update method. Check the lock_by_size field that we’re interested in.

pict14

We have a hash that consists of symbols and boolean values.

Run step command to get into the update method. Pry-binding doesn’t support var args as byebug does, so to check the passing data, we type the name of the method attributes.

pict15

Data we pass to the function will have strings instead of symbols. We can guess that our @product won’t be updated properly.

If we don’t know where we currently are in a code, (for example: we run too many commands and we don’t see the exact code) using the whereami command is very handy. View the source code of the method you are currently within.

pict16

Come back to the previous method using up command, and check the state of the locked_by_size field again.

pict17

As we thought, the locked_by_size field was saved with the wrong data. The good thing is that you know how to use the  Pry-Byebug debugger now, and you fixed the bug one more time!

You’re very persistent if you managed to get to the end of this post. 🙂 I hope this  tutorial was useful for you Thank you for following along and happy debugging!

Send this to a friend