Debugging Rails Applications ============================ This guide covers how to debug Ruby on Rails applications. By referring to this guide, you will be able to: * Understand the purpose of debugging * Track down problems and issues in your application that your tests aren't identifying * Learn the different ways of debugging * Analyze the stack trace == View Helpers for Debugging One common task is to inspect the contents of a variable. In Rails, you can do this with three methods: * `debug` * `to_yaml` * `inspect` === debug `debug` will return a
-tag that has object dumped by YAML. Generating readable output to inspect any object.

[source, html]
----------------------------------------------------------------------------
<%= debug @post %>

  Title:
  <%=h @post.title %>

----------------------------------------------------------------------------

Will render something like this:

----------------------------------------------------------------------------
--- !ruby/object:Post
attributes:
  updated_at: 2008-09-05 22:55:47
  body: It's a very helpful guide for debugging your Rails app.
  title: Rails debugging guide
  published: t
  id: "1"
  created_at: 2008-09-05 22:55:47
attributes_cache: {}


Title: Rails debugging guide
----------------------------------------------------------------------------

=== to_yaml

Displaying an instance variable, or any other object or method, in yaml format can be achieved this way:

[source, html]
----------------------------------------------------------------------------
<%= simple_format @post.to_yaml %>

  Title:
  <%=h @post.title %>

----------------------------------------------------------------------------

`to_yaml` converts the method to yaml format leaving it more readable and finally `simple_format` help us to render each line as in the console. This is how `debug` method does its magic.

As a result of this, you will have something like this in your view:

----------------------------------------------------------------------------
--- !ruby/object:Post
attributes:
updated_at: 2008-09-05 22:55:47
body: It's a very helpful guide for debugging your Rails app.
title: Rails debugging guide
published: t
id: "1"
created_at: 2008-09-05 22:55:47
attributes_cache: {}

Title: Rails debugging guide
----------------------------------------------------------------------------

=== inspect

Another useful method for displaying object values is `inspect`, especially when working with arrays or hashes, it will print the object value as a string, for example:

[source, html]
----------------------------------------------------------------------------
<%= [1, 2, 3, 4, 5].inspect %>

  Title:
  <%=h @post.title %>

----------------------------------------------------------------------------

Will be rendered as follows:

----------------------------------------------------------------------------
[1, 2, 3, 4, 5]

Title: Rails debugging guide
----------------------------------------------------------------------------

== The Logger

=== What is it?

Rails makes use of ruby's standard `logger` to write log information. You can also substitute another logger such as `Log4R` if you wish.

If you want to change the logger you can specify it in your +environment.rb+ or any environment file.

[source, ruby]
----------------------------------------------------------------------------
ActiveRecord::Base.logger = Logger.new(STDOUT)
ActiveRecord::Base.logger = Log4r::Logger.new("Application Log")
----------------------------------------------------------------------------

Or in the `__Initializer__` section, add _any_ of the following

[source, ruby]
----------------------------------------------------------------------------
config.logger = Logger.new(STDOUT)
config.logger = Log4r::Logger.new("Application Log")
----------------------------------------------------------------------------

[TIP]
By default, each log is created under `RAILS_ROOT/log/` and the log file name is +environment_name.log+.

=== Log Levels

When something is logged it's printed into the corresponding log if the message log level is equal or higher than the configured log level. If you want to know the current log level just call `ActiveRecord::Base.logger.level` method.

The available log levels are: +:debug+, +:info+, +:warn+, +:error+, +:fatal+, each level has a log level number from 0 up to 4 respectively. To change the default log level, use

[source, ruby]
----------------------------------------------------------------------------
config.log_level = Logger::WARN # In any environment initializer, or
ActiveRecord::Base.logger.level = 0 # at any time
----------------------------------------------------------------------------

This is useful when you want to log under development or staging, but you don't want to flood your production log with unnecessary information.

[TIP]
Rails default log level is +info+ in production mode and +debug+ in development and test mode.

=== Sending Messages

To write in the current log use the `logger.(debug|info|warn|error|fatal)` method from within a controller, model or mailer:

[source, ruby]
----------------------------------------------------------------------------
logger.debug "Person attributes hash: #{@person.attributes.inspect}"
logger.info "Processing the request..."
logger.fatal "Terminating application, raised unrecoverable error!!!"
----------------------------------------------------------------------------

A common example:

[source, ruby]
----------------------------------------------------------------------------
class PostsController < ApplicationController
  # ...

  def create
    @post = Post.new(params[:post])
    logger.debug "New post: #{@post.attributes.inspect}"
    logger.debug "Post should be valid: #{@post.valid?}"

    if @post.save
      flash[:notice] = 'Post was successfully created.'
      logger.debug "The post was saved and now is the user is going to be redirected..."
      redirect_to(@post)
    else
      render :action => "new"
    end
  end

  # ...
end
----------------------------------------------------------------------------

Will be logged like this:

----------------------------------------------------------------------------
Processing PostsController#create (for 127.0.0.1 at 2008-09-08 11:52:54) [POST]
  Session ID: BAh7BzoMY3NyZl9pZCIlMDY5MWU1M2I1ZDRjODBlMzkyMWI1OTg2NWQyNzViZjYiCmZsYXNoSUM6J0FjdGlvbkNvbnRyb2xsZXI6OkZsYXNoOjpGbGFzaEhhc2h7AAY6CkB1c2VkewA=--b18cd92fba90eacf8137e5f6b3b06c4d724596a4
  Parameters: {"commit"=>"Create", "post"=>{"title"=>"Debugging Rails", "body"=>"I'm learning how to print in logs!!!", "published"=>"0"}, "authenticity_token"=>"2059c1286e93402e389127b1153204e0d1e275dd", "action"=>"create", "controller"=>"posts"}
New post: {"updated_at"=>nil, "title"=>"Debugging Rails", "body"=>"I'm learning how to print in logs!!!", "published"=>false, "created_at"=>nil}
Post should be valid: true
  Post Create (0.000443)   INSERT INTO "posts" ("updated_at", "title", "body", "published", "created_at") VALUES('2008-09-08 14:52:54', 'Debugging Rails', 'I''m learning how to print in logs!!!', 'f', '2008-09-08 14:52:54')
The post was saved and now is the user is going to be redirected...
Redirected to #
Completed in 0.01224 (81 reqs/sec) | DB: 0.00044 (3%) | 302 Found [http://localhost/posts]
----------------------------------------------------------------------------

Notice the logged lines, now you can search for any unexpected behavior in the output.

By now you should know how to use the logs in any environment. Remember to take advantage of the log levels and use them wisely, mostly in production mode.

== Debugging with ruby-debug

Many times your code may not behave as you expect, sometimes you will try to print in logs, console or view values to make a diagnostic of the problem.

Unfortunately, you won't find always the answer you are looking for this way. In that case, you will need to know what's happening and adventure into Rails, in this journey the debugger will be your best companion.

If you ever wanted to learn about Rails source code but you didn't know where to start, this may be the best way, just debug any request to your application and use this guide to learn how to move in the code you have written but also go deeper into Rails code.

=== Setup

Ruby-debug comes as a gem so to install, just run:

----------------------------------------------------------------------------
$ sudo gem in ruby-debug
----------------------------------------------------------------------------

In case you want to download a particular version or get the source code, refer to link:http://rubyforge.org/projects/ruby-debug/[project's page on rubyforge].

Rails has built-in support for ruby-debug since April 28, 2007. Inside any Rails application you can invoke the debugger by calling the `debugger` method.

Let's take a look at an example:

[source, ruby]
----------------------------------------------------------------------------
class PeopleController < ApplicationController
  def new
    debugger
    @person = Person.new
  end
end
----------------------------------------------------------------------------

If you see the message in the console or logs:

----------------------------------------------------------------------------
***** Debugger requested, but was not available: Start server with --debugger to enable *****
----------------------------------------------------------------------------

Make sure you have started your web server with the option --debugger:

----------------------------------------------------------------------------
~/PathTo/rails_project$ script/server --debugger
----------------------------------------------------------------------------

[TIP]
In development mode, you can dynamically `require \'ruby-debug\'` instead of restarting the server, in case it was started without `--debugger`.

In order to use Rails debugging you'll need to be running either *WEBrick* or *Mongrel*. For the moment, no alternative servers are supported.

=== The Shell

As soon as your application calls the `debugger` method, the debugger will be started in a debugger shell inside the terminal window you've fired up your application server and you will be placed in the ruby-debug's prompt `(rdb:n)`. The _n_ is the thread number.

If you got there by a browser request, the browser will be hanging until the debugger has finished and the trace has completely run as any normal request.

For example:

----------------------------------------------------------------------------
@posts = Post.find(:all)
(rdb:7)
----------------------------------------------------------------------------

Now it's time to play and dig into our application. The first we are going to do is ask our debugger for help... so we type: `help` (You didn't see that coming, right?)

----------------------------------------------------------------------------
(rdb:7) help
ruby-debug help v0.10.2
Type 'help ' for help on a specific command

Available commands:
backtrace  delete   enable  help    next  quit     show    trace
break      disable  eval    info    p     reload   source  undisplay
catch      display  exit    irb     pp    restart  step    up
condition  down     finish  list    ps    save     thread  var
continue   edit     frame   method  putl  set      tmate   where
----------------------------------------------------------------------------

[TIP]
To view the help menu for any command use `help ` in active debug mode. For example: _help var_

The second command before we move on, is one of the most useful command: `list` (or his shorthand `l`).

This command will give us a starting point of where we are by printing 10 lines centered around the current line; the current line here is line 6 and is marked by =>.

----------------------------------------------------------------------------
(rdb:7) list
[1, 10] in /PathToProject/posts_controller.rb
   1  class PostsController < ApplicationController
   2    # GET /posts
   3    # GET /posts.xml
   4    def index
   5      debugger
=> 6      @posts = Post.find(:all)
   7
   8      respond_to do |format|
   9        format.html # index.html.erb
   10        format.xml  { render :xml => @posts }
----------------------------------------------------------------------------

If we do it again, this time using just `l`, the next ten lines of the file will be printed out.

----------------------------------------------------------------------------
(rdb:7) l
[11, 20] in /PathTo/project/app/controllers/posts_controller.rb
   11      end
   12    end
   13
   14    # GET /posts/1
   15    # GET /posts/1.xml
   16    def show
   17      @post = Post.find(params[:id])
   18
   19      respond_to do |format|
   20        format.html # show.html.erb
----------------------------------------------------------------------------

And so on until the end of the current file, when the end of file is reached, it will start again from the beginning of the file and continue again up to the end, acting as a circular buffer.

=== The Context
When we start debugging your application, we will be placed in different contexts as you go through the different parts of the stack.

A context will be created when a stopping point or an event is reached. It has information about the suspended program which enable a debugger to inspect the frame stack, evaluate variables from the perspective of the debugged program, and contains information about the place the debugged program is stopped.

At any time we can call the `backtrace` command (or alias `where`) to print the backtrace of the application, this is very helpful to know how we got where we are. If you ever wondered about how you got somewhere in your code, then `backtrace` is your answer.

----------------------------------------------------------------------------
(rdb:5) where
    #0 PostsController.index
       at line /PathTo/project/app/controllers/posts_controller.rb:6
    #1 Kernel.send
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/base.rb:1175
    #2 ActionController::Base.perform_action_without_filters
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/base.rb:1175
    #3 ActionController::Filters::InstanceMethods.call_filters(chain#ActionController::Fil...,...)
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/filters.rb:617
...
----------------------------------------------------------------------------

You move anywhere you want in this trace using the `frame _n_` command, where _n_ is the specified frame number.

----------------------------------------------------------------------------
(rdb:5) frame 2
#2 ActionController::Base.perform_action_without_filters
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/base.rb:1175
----------------------------------------------------------------------------

The available variables are the same as if we were running the code line by line, after all, that's what debugging is.

Moving up and down the stack frame: You can use `up [n]` (`u` for abbreviated) and `down [n]` commands in order to change the context _n_ frames up or down the stack respectively. _n_ defaults to one.

=== Threads

The debugger can list, stop, resume and switch between running threads, the command `thread` (or the abbreviated `th`) is used an allows the following options:

* `thread` shows the current thread.
* `thread list` command is used to list all threads and their statuses. The plus + character and the number indicates the current thread of execution.
* `thread stop _n_` stop thread _n_.
* `thread resume _n_` resume thread _n_.
* `thread switch _n_` switch thread context to _n_.

This command is very helpful, among other occasions, when you are debugging concurrent threads and need to verify that there are no race conditions in your code.

=== Inspecting Variables

Any expression can be evaluated in the current context, just type it!

In the following example we will print the instance_variables defined within the current context.

----------------------------------------------------------------------------
@posts = Post.find(:all)
(rdb:11) instance_variables
["@_response", "@action_name", "@url", "@_session", "@_cookies", "@performed_render", "@_flash", "@template", "@_params", "@before_filter_chain_aborted", "@request_origin", "@_headers", "@performed_redirect", "@_request"]
----------------------------------------------------------------------------

As you may have figured out, all variables that you can access from a controller are displayed, lets run the next line, we will use `next` (we will get later into this command).

----------------------------------------------------------------------------
(rdb:11) next
Processing PostsController#index (for 127.0.0.1 at 2008-09-04 19:51:34) [GET]
  Session ID: BAh7BiIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNoSGFzaHsABjoKQHVzZWR7AA==--b16e91b992453a8cc201694d660147bba8b0fd0e
  Parameters: {"action"=>"index", "controller"=>"posts"}
/PathToProject/posts_controller.rb:8
respond_to do |format|
-------------------------------------------------------------------------------

And we'll ask again for the instance_variables.

----------------------------------------------------------------------------
(rdb:11) instance_variables.include? "@posts"
true
----------------------------------------------------------------------------

Now +@posts+ is a included in them, because the line defining it was executed.

[TIP]
You can also step into *irb* mode with the command `irb` (of course!). This way an irb session will be started within the context you invoked it. But you must know that this is an experimental feature.

To show variables and their values the `var` method is the most convenient way:

----------------------------------------------------------------------------
var
(rdb:1) v[ar] const