Debugging Ruby

(1)

(2)

Debugging Ruby code & Rails applications by example

Ryan Bigg

This book is for sale athttp://leanpub.com/debuggingruby This version was published on 2014-10-16

This is aLeanpubbook. Leanpub empowers authors and publishers with the Lean Publishing process.Lean Publishingis the act of publishing an in-progress ebook using lightweight tools and many iterations to get reader feedback, pivot until you have the right book and build traction once you do.

(3)

Please help Ryan Bigg by spreading the word about this book onTwitter! The suggested hashtag for this book is#debuggingruby.

Find out what other people are saying about the book by clicking on this link to search for this hashtag on Twitter:

(4)

General Debugging Tips . . . . 1

Debugging frame of mind . . . 1

Debugging Ruby . . . . 3 Basic Example #1 . . . 3 Basic Example #2 . . . 3 Basic Example #2 . . . 5 Debugging Rails . . . . 9 Workflow . . . 9

Rails Example #1 - form_for . . . 9

Rails Example #2 - Routing HTTP verbs/methods . . . 20

Debugging slow code . . . 27

TODO . . . 30

Handling Exceptions . . . 31

Advanced Rails Debugging . . . 32

(5)

Thank you for reading Debugging Ruby.

If you find any misteaks while reading this book, please email them to [email protected]. If email’s not your thing, I have a review tool that you can use too. I’ll need your email address to add you to that though. Tweet me (@ryanbigg) or email is cool.

If it’s a problem to do with your code, then please put the code on GitHub and link me to it so I can clone it and attempt to reproduce the problem myself. If you don’t understand something, then it’s more likely that I’m the idiot and rushed it when I wrote it. Let me know!

If you want to see some code examples and compare them to what you have, you can go view them over on GitHub¹. For now, they’re the absolute latest code from the book.

This far into the book and there’s already one error. You should expect that it is not alone. It has friends and their ways are devious. They are coming after your perception of reality. Beware.

I’ve been helping out in the #rubyonrails channel on Freenode now for about 7 years and I’ve seen a wide variety of skill levels come through. I also help out frequently on Stack Overflow and my day job requires doing some of that as well. More often than not though, the visitors of the channel or people on Stack Overflow are just lacking the basic skills for debugging their code.

The ability to debug code is arguably more important than the ability to write code. Writing code is easy! Just throw some things together and bash them a couple of times until it works. What could possibly go wrong? Anything and everything.

Code is not perfect the first time it is written, or even the 10th time it is rewritten. The ability to debug code written by ourselves, strangers – or versions of us from the past that can feel like strangers sometimes – is a valuable ability to have. When things go wrong – and they will go wrong – having that ability allows you to dive in without fear into fixing whatever code is causing the fault quickly and efficiently so you can get back to doing more productive things.

Debugging can be fun because it provides a technical challenge; a puzzle. Deciphering that puzzle is usually just a matter of walking through the flow of execution within the piece of code which is breaking, but it is sometimes hard to know where the right place to start is. Once you’ve found the place to start, knowing where to go from there can also be difficult. The solution is its own reward and if you’re anything like me you should get a nice little Dopamine hit every time you solve a bug. Or even one of those from just helping out other people by “squashing” bugs they’ve reported. Within this book are common examples things that can go wrong in Ruby and Rails code. Ranging anywhere from a typo in the code, to performance issues and nasty exceptions. This book will cover a wide gamut of how code can break, and exactly what we can do about it to fix those breakages and ensure that we know about them as soon as possible.

Let’s go!

(6)

The ability to debug code is arguably more important than the ability to write code. Written code is sometimes not completely perfect the first time it’s written, especially when humans are involved in the writing of that code. Humans make mistakes, and those mistakes can cost time and money. Being able to fix those mistakes in an efficient manner is a core competency to being a good programmer. These mistakes are sometimes extremely simple; a typo here, a missing bracket there, defining code outside of the correct scope. Other times they involve interconnected bits of code and tracking down the misbehaving cog (or cogs) in that wonderful machine can take some time.

In this book, we’re going to go through some common coding mistakes that people make and we will look at how to solve them. The deeper and deeper you get into this book, the more complicated the examples will get. All the examples in this book will be written in Ruby.

Before we get to see any code, let’s talk about getting in the right frame of mind for debugging.

Debugging frame of mind

Have you ever come across a bug that’s been too hard to fix, only to have the answer come to you after you distract yourself from the problem for an extended period of time? I most certainly have. I think that just by sitting there for a bit longer that I can magically know the answer. Most of the time that this is not true. There are many other ways to solve the problem, but I focus on my current line of thinking and get caught up in a frustrating loop. The loop is thinking that I can solve the problem, attempting to solve it and then not being able to solve it.

I’ve solved these kinds of problems by sleeping, having lunch², exercising or by talking people in the community and asking them about the problem. These are all common sense, but it’s worth covering them even if it is for a short while.

Sleep has the best effect on my ability to debug. A good night’s sleep is easy to come by as I’m a newly married man who lives in a first-world country and I’m thankful for all of those things. Sleeping well makes me less grumpy, more rational in my thinking and generally improves my mood and outlook on things. Debugging on low sleep leads only to frustration.

Similarly, eating (and eating healithly) also helps. Having to debug something when my stomach is rumbling is hard work. Staying the course and attempting to fix the problem is not the best course of action, but I still do it anyway. Grabbing something to eat helps a lot with that. If it’s some lollies, then the initial sugar hit boosts me up, but then comes the inevitable crash. Eating healthily improves my long-term ability to debug well, and so I try to do that as often as I can.

²Hence the book’s subtitle “How to find the answer to your problems in a sandwich”. Realistically for me though it would be an Indian curry, Thai dish, salad, burger or yiros. Sandwich just has a better ring to it than all those other things.

(7)

Exercising has been scientifically proven³ ⁴ ⁵to enhance brain power (and general happiness!), and along with that comes the ability to reason better about code. Going for a walk, riding a bike or a session at the gym are all ways that I think have boosted my ability to debug code.

Lastly, talking to other people is absolutely worthwhile. I’ve found the answer to many a problem by just simply explaining what’s going wrong to someone else. This technique is called the Rubber Ducky Technique. You talk to the person, they say nothing (or very little), and suddenly an epiphany happens. The answer is known. It’s a funny thing.

If the answer doesn’t come by way of explanation, other people have their own brains to reason about things with and their own takes on things. The way that you debug something might be different to the way that they debug it. Getting someone else to look over the code and work with me in reasoning about a problem is, by far, the most productive debugging technique that I know of.

So in summary: make sure you’ve caught up on your sleep, have eaten well, have exercised well, and don’t be afraid to speak to other people in the Ruby community about any issues you have. Let’s now dive into some practical examples of debugging in Ruby.

³http://www.psychologytoday.com/blog/the-athletes-way/201401/what-is-the-best-way-improve-your-brain-power-life ⁴http://www.apa.org/gradpsych/2013/09/exercise.aspx

(8)

In this chapter we’ll cover some basic Ruby code that has some small problems with it, and figure out how to fix it so that the code works once again.

Basic Example #1

Our first problem we can cause ourselves in theirb console. Let’s start this up now by usingirb and put this in it:

1 "test".join

When we type this and hit enter, we’ll see aNoMethodErrorexception:

1 irb(main):001:0> "test".join

2 NoMethodError: undefined method `join' for "test":String 3 from (irb):1

4 from .../ruby-2.1.3/bin/irb:11:in `<main>'

This exception shows us that something exceptional happened with our code – namely aNoMethodError. The text after NoMethodErrorshows more detail about what happened, and then the lines under-neath it show us how the script got to that point, starting from the bottom up, and that’s called a

stack trace.

Why are we getting this error? Well, the"test"object is an object of typeString, as is indicated on the first line of our exception output with the words"test":String. If we look atthe documentation

for Ruby’s String class⁶, we can see that there is indeed no method calledjoin.

This error is happening because we’re calling a method that doesn’t exist. In this example we’ve seen what a stack trace is and how to read it. The example is slightly contrived, but nevertheless demonstrates how we can find what’s happening.

Let’s take a look at a proper Ruby program which has another, similar bug and talk more about stack traces.

Basic Example #2

Let’s take a look at our first very simple Ruby script with an error: ⁶http://www.ruby-doc.org/core-2.1.3/String.html

(9)

class Car

attr_accesssor :on

end

This is some fairly simple Ruby code. All we’re doing is defining a class calledCarand then calling theattr_accesssormethod inside that class which should define a setter method calledon=where we can store a value, and a getter method called on where we can retrieve that value. We don’t necessarily care about the setting and getting just yet. All we care about is that our code works. Put this code into a new file calledcar.rband try running it with ruby car.rb. Ideally, nothing should be output to the terminal, because we have not told Ruby to output anything. Instead of nothing, you should see this:

car.rb:2:in `<class:Car>':

undefined method `attr_accesssor' for Car:Class (NoMethodError) from car.rb:1:in `<main>'

The output here is modified slightly to fit into the book. The first two lines in the above output should be one line. This is another stack trace, just like the one we saw in the earlier example. These are output by any Ruby program that encounters an exceptional circumstance and it shows us the execution flow of the program in reverse order. Let’s start from the final line of the stacktrace: from car.rb:1:in `<main>'

This line tells us that the execution flow of the program started on line 1 of thecar.rb file. The <main>here indicates the main namespace that all code within Ruby operates in. This line of the stacktrace is not too important. All it’s indicating is that on line 1 of our program, something is executing and altering what our program is going to do.

The first line of the stacktrace begins with this: car.rb:2:in `<class:Car>'

This line tells us that on line 2 of car.rb, we’re operating within the scope of a class called Car (<class:Car>). Because this is the top line of the stacktrace, this is probably where our error has occurred. In most cases, the top line of the stacktrace will point to the exact line where an error occurs.

The remainder of this line is this:

(10)

This part of it tells us the error that’s happened. In this case, we’re trying to call a method that Ruby has no knowledge of, theattr_accesssormethod. We’re trying to call that method on theCarclass, but that method does not exist there. When we try to call a method that Ruby does not know about, it raises aNoMethodErrorexception, which is shown in parentheses at the end of the line.

Our program is 3 lines long, but the third line is just an end, and those are never included in stacktraces because they’re just there to demarcate the end of a scope within the code, rather than perform a function.

From this stacktrace, we can gather that the error is happening on line 2. All we’re doing on line 2 is this:

attr_accesssor :on

Do you see the mistake we’ve made yet? It might be glaringly obvious or it might not be. Look at it for a moment longer. Do you see it now?

The mistake we’ve made is dead simple: we’ve typed three “s”es rather than two. We’ve done attr_-accesssor, rather thanattr_accessor. The code should be this:

attr_accessor :on

Change the code on line 2 to that now and re-run the program. It should run without showing anything. This is the standard for Ruby programs when they execute successfully. Unless we have specifically told it to output anything – i.e. with a call to theputsmethod – nothing will happen.

Verify program success

You can verify that a program has run successfully by running this command (assuming you’re using Bash or a similar shell):

1 echo $?

If that outputs0, then everything has worked correctly.

TODO: Bash error codes mention goes here.

Now that we’ve fixed that error, let’s cover another.

Basic Example #2

(11)

class Car attr_accessor :on def start on = true end end

car = Car.new car.start puts car.on

Can you tell what it’s doing just by looking at it? It defines a new class calledCar, and a virtual attribute inside that class by way of attr_accessor calledon. This time,attr_accessoris spelled correctly. Remember that the attr_accessor call defines a getter method called on and a setter method calledon=.

After theattr_accessor, the code defines a method calledstartwhich setsontotrue. It then ends the method and class definition.

On the final two lines, the code creates a new instance of this class withCar.newand assigns it to a local variable, callsstartwhich should do what it’s told, and finally outputs the value ofcar.on usingputs. Just by looking at this code, you may expect that when it is run that it will outputtrue. You’d be wrong.

Put this code intocar.rband try running it. This is what will happen:

$ ruby car.rb $

Rather than nothing being output this time, a blank line has been output. This is because the program has done what we’ve told it to do. It does not outputtrue, even though thestartmethod is setting onto true. This time we don’t have a stacktrace to tell us what line the error is probably on. We have to step through the program’s execution ourselves.

Since there are no exceptions raised within the code, we can assume that the code itself is valid. Let’s step through the final three lines of the code:

The first line here creates a new instance of theCarclass. That’s Ruby’s code, so that’s probably not the source of our frustration. The second line calls thestartmethod which setsontotrue. The final line just outputs the value of on, which isn’t too special a task. The problem probably lies within our second line. Let’s look at how that method is defined:

(12)

def start

on = true end

This code inside the method is not dissimilar to the first line of the previous example: car = Car.new

When we callcar = Car.newwe’re setting a local variable to the value of whateverCar.newreturns. In the start method, we’re setting an on local variable to true. This is not our intention! Our intention is to set the virtual attribute for the instance totrue. Beware this very fine difference! There’s more than one way to set this virtual attribute. We can go through the setter method call, like this:

def start

self.on = true end

The caveat of this is that theon=method may define other behaviour. This is a rare occurrence in Ruby code, but it can happen. In this case, it’s obvious that theon= method isn’t redefined to add extra behaviour, so it’s OK to do this. Another way of doing it would be to set the instance variable of the same name, like this:

def start @on = true end

Doing it this way has the benefit of the code being shorter and there being no unintended side-effects with theon=method. Using either the setter method or setting the instance variable are both legitimate ways of solving the issue with our code. Go ahead and try both ways now. They should both cause the program to output this when it’s run:

$ ruby car.rb true

Great, so we’ve solved this problem. The issue here was that we were trying to set a local variable inside the method, rather than referencing the virtual attribute setter method or instance variable. With that out of the way, let’s look at the possibility of a setter method behaving badly as we talked about before. Let’s change our code to this:

(13)

class Car attr_accessor :on def start self.on = true end def on=(value) @on = !value end end

Thestartmethod is now using the setter method,on=, to set the value of the virtual attribute called on. The setter method is overriden from the default here directly underneath that. It takes the value and negates it, and then stores it on that@on instance variable. This means that when we callon, we’ll get the opposite of what it should be: setting it totruewill make itfalseand vice versa. Try running this code yourself now and you’ll see:

$ ruby car.rb false

Theon=method is maliciously negating our value, giving us an unexpected outcome. If we set the instance variable within thestartmethod directly, this would bypass theon=method and we would see the right value. Thestartmethod would look like this:

def start @on = true end

And the output of the program would look like this: $ ruby car.rb

true

It’s extremely rare that a setter method will perform strange functions like this, but it still is worthwhile knowing that it can happen, just in case we come across a situation like this in our debugging experiences.

(14)

Rails applications are generally more complex than one or two files. More often than not, you’ll have many different pieces of the application all working together: the routes, the controllers, the models, the views and the helpers. In this chapter, we’ll cover some examples of errors that people make within Rails applications and how to fix them.

Workflow

Each section below works through one particular problem in a Rails application. These Rails applications are kept on GitHub athttps://github.co m/radar/debugging_book_examples⁷ and are numbered the same way as their examples; i.e. Example #1’s code is within the directory called “1” underneath the “rails” directory.

To work through the examples of these Rails applications, you’ll need to clone that repository to your computer:

git clone git://github.com/radar/debugging_book_examples

Each Rails application comes fitted with RSpec and Capybara tests which will pass once the code has been fixed. We can run these tests to execute some code which wil check if the application is working. Running automated tests is just an easier way compared with manually viewing the application ourselves and saves time in the long run as our applications get more and more complex. Let’s begin with the first example now.

Rails Example #1 - form_for

In this example we’ll cover:

• Thedebughelper • How to read log output

• How constant lookup in Ruby works

In this first application example, we have a very basic Rails application. The thing that we want this application to do right now is for the users to be able to go to the “New Post” page without any issues, but unfortunately there’s a problem that’s preventing them from doing that which we’ll see shortly.

Before we do anything with this application, let’s install all the dependencies: ⁷https://github.com/radar/debugging_book_examples

(15)

bundle install

Now let’s look at the automated test we have inside spec/features/posts_spec.rb inside the application, written using RSpec and Capybara’s DSL:

require 'spec_helper' feature "Posts" do

it "can begin to create a new post" do visit root_path

click_link 'New Post' find_field("Title") find_field("Body") end

end

This test will pass if it can navigate to the root page, click ‘New Post’ and see two fields, one for “Title” and one for “Body”. If we run the test now, we’ll see this error:

1) Posts can begin to create a new post Failure/Error: click_link 'New Post' ActionView::Template::Error:

First argument in form cannot contain nil or be empty # ./app/views/posts/new.html.erb:1:in `...'

# ./spec/features/posts_spec.rb:6:in `block (2 levels) in <top (required)>'

This is a typical failure output from RSpec, shown when code raises an exception. The first line of the message shows us which test is failing. We should have a pretty good idea which test that is out of the one test that we have so far. The particular exception that we’re seeing with this test is ActionView::Template::Error, and the message for that exception is “First argument in form cannot contain nil or be empty”. We’ll get to that in a moment.

The two remaining lines in this output show some of the stacktrace for the error. It shows us that posts_spec.rb line 6 does something that triggers some code inapp/views/posts/new.html.erb to run, and that’s where the error is (probably) occurring. According to the stacktrace, that’s line 1 of app/views/posts/new.html.erb.

All this application has inside it is aPostsControllerwhich does nothing other than inherit from ApplicationController. This controller is routed to by the two routes withinconfig/routes.rb:

(16)

Bug::Application.routes.draw do root "posts#index"

resources :posts

end

We have a view atapp/views/posts/index.html.erbwhich just contains a link to the new action:

<%= link_to "New Post", new_post_path %>

When we go to thatnew_post_path, it will renderapp/views/posts/new.html.erbwhich contains this content:

<h2>Writing a new post</h2>

<%= form_for @post do |f| %> <p> <%= f.label :title %><br> <%= f.text_field :title %> </p> <p> <%= f.label :body %><br> <%= f.text_area :body %> </p> <%= f.submit %> <% end %>

So that’s all we have: some routes, a controller that does nothing special, a template atapp/views/posts/index.html.erb and another atapp/views/posts/new.html.erb. Just four interconnected pieces in this application,

nothing too special.

Let’s jump back to our test now and see what it said when we ran it with bundle exec rspec spec/features/posts_spec.rb.

1) Posts can begin to create a new post Failure/Error: click_link 'New Post' ActionView::Template::Error:

First argument in form cannot contain nil or be empty # ./app/views/posts/new.html.erb:1:in `...'

(17)

<%= form_for @post do |f| %>

All we’re doing on this line is calling theform_formethod and passing it the@postinstance variable and then starting a block. Later on in that file, we’re calling some methods on the block argument, but that doesn’t really matter. The error is fair-and-square happening on this line. The most useful part of the error message is the message for the exception:

First argument in form cannot contain nil or be empty

The argument that it’s talking about here is the@postvariable that we’re passing. It’s claiming that the variable isnilor empty, and it probably is.

The debug helper

We can see for ourselves if this variable is actuallynilby removing all the code inapp/views/posts/new.html.erb and replacing it with this single line:

<%= debug @post.inspect %>

Thedebugmethod here is provided by Rails and will output a YAML’ized version of whatever it is passed. We’re passing to it the output of [email protected]. Theinspectmethod is a method provided by Ruby which outputs a human-friendly version of the object. If you’ve ever written Ruby inirb, you’ve seen the inspected versions of objects perhaps without even realising it.

Start a newirbsession now and try entering these things:

• 1 • 1.inspect • puts 1.inspect • "1" • "1".inspect • puts "1".inspect • [1,2,3] • [1,2,3].inspect • puts [1,2,3].inspect • nil • nil.inspect • puts nil.inspect

(18)

We’ll see that the non-inspectversions are almost identical to theinspectversions. Theinspect versions just have more quotes around them. This is because the inspect call always returns a Stringobject, as those are easiest for humans to read. Whatever the final thing is on the line for some code entered into IRB is what will be returned in the IRB prompt. In the case of the puts calls, IRB returnsnilbecauseputsreturnsnil. IRB automatically usesinspectto return a human-friendly representation of whatever is entered into the prompt.

Thedebugmethod in our view will not automatically callinspecton whatever it is passed. Instead, it calls another method:to_s. In some cases this method gives back similar output toinspect. Try the above examples withto_srather thaninspectand see what happens.

For everything including nil we see a string representation of that object. For the number1we see "1". For the string"1", we see the object again because it’s already a string. Converting an Array to a String gives us"[1,2,3]", which clearly shows us that the object is an array consisting of the elements1,2and3.

Callingnil on the other hand, produces nothing; just an empty string (“”). That’s because nilis nothing. This whole explanation was to demonstrate that calling this code is not enough:

<%= debug @post %>

Due to thedebugmethod callingto_srather thaninspecton the objects it is passed. We must call inspectourselves:

<%= debug @post.inspect %>

This way, thedebugmethod receives a String object already and will just output that. Now let’s see this in action by firing up a new server process with this application: rails server

Navigating to http://localhost:3000 will show just the “New Post” button. We know that the root action works because our test is not failing on that line. Clicking “New Post” now will show us the output of thedebugcall, which will be this:

--- nil ...

We can see here that our @post variable is indeed nil, just like the error message said: “First

argument in form cannot contain nil or be empty”. Now why is this?

We know that the route is working correctly because we’re currently on the page at /posts/new looking at the debug message we put there. The route routes to the controller, and the controller is

(19)

empty. After the controller runs, the view template is rendered. Nowhere along the chain is the@post variable defined for ourform_forcall in app/views/posts/new.html.erband that is the cause of this bug.

Where should we be defining this variable? Not in the view itself, because it is never the responsibility of the view to collect data. That is the controller’s job, and so the code to define the@postvariable should go in the controller. But where in the controller?

A clue lies in the server output over in our console.

Reading log output

When we made a request to/posts/new, it shows this:

Started GET "/posts/new" for 127.0.0.1 at 2013-11-09 11:29:09 +1100 Processing by PostsController#new as HTML

Rendered posts/new.html.erb within layouts/application (0.6ms) Completed 200 OK in 4ms (Views: 3.6ms | ActiveRecord: 0.0ms)

This text has a whole lot of information compressed into a little bit of space. Knowing how to read and interpret logs from Rails is an important skill, so let’s go through the details of this now. On the first line we have the details about the request:

Started GET "/posts/new" for 127.0.0.1 at 2013-11-09 11:29:09 +1100

This shows us that we have made aGETrequest to the application, requesting the/posts/newpath. The next two bits of information is the IP address of our local computer and the timestamp for the request.

On the second line we have this:

Processing by PostsController#new as HTML

This indicates to us that the route has been matched by Rails and has routed to thePostsController’s newaction. The request is a standard HTML format, meaning that HTML output will be returned by this request.

The third line is this:

Rendered posts/new.html.erb within layouts/application (0.6ms)

This tells us that the posts/new.html.erb template was rendered within layouts/application. This means that the controller has automatically chosen to display this template for this action, and has used the default layout for the application to wrap around that template. All the rendering took 0.6ms in this case.

(20)

Completed 200 OK in 4ms (Views: 3.6ms | ActiveRecord: 0.0ms)

This line tells us that the response was completed successfully and returned a200 OKresponse. This is the HTTP status part of the response which indicates to browsers the final status of their request. We can see that the request completed in 4ms total, with the views taking 3.6ms of that time and ActiveRecord taking no time at all. The remaining 0.4ms were taken up by unknown things.

Logs are written to files

If you want to go back and see what happened after you’ve shut down the server, we’ll be able to do that by viewinglogs/development.log, which stores the exact same data that

is displayed when the server is running. Thelogsdirectory is where Rails writes its log

data to, and the filename is simply the environment that the Rails application is running within. By default, that environment is “development”, so the log file that will be written to will belogs/development.log.

We know that we need to define the@postvariable within the controller to make it available to the view, but where exactly? The logs tell us where exactly:

Processing by PostsController#new as HTML

This line from the logs is telling us that thenew action within thePostsController is being run before the view is rendered. This would be a perfect place to set up the variable, so let’s do that now by defining this code:

app/controllers/posts_controller.rb

1 class PostsController < ApplicationController

2 def new

3 @post = Post.new

4 end

5 end

Is this enough to fix our test? Let’s find out by runningbundle exec rspec spec/features/posts_-spec.rb.

(21)

1) Posts can begin to create a new post Failure/Error: click_link 'New Post' NameError:

uninitialized constant PostsController::Post # ./app/controllers/posts_controller.rb:3:in `new'

Not quite! We’re now seeing a new error which is aNameErrorexception. This time it’s happening from line 3 of thePostsController, which is this line:

@post = Post.new

The error says “uninitialized constant PostsController::Post”, but on this line we’re not looking up thePostsController::Postconstant, we just want Post! So what’s happening here? Why does it sayPostsController::Postand not justPost?

Constant lookups in Ruby

When Ruby attempts to look up a constant, it will first attempt to look it up within the current constant context. Because we’re within thePostsController, it will attempt to look it up there. It will then travel up the hierarchy looking for that constant until it reaches the top-level namespace. If it can’t find it there, then it gives up and shows an error message saying that it couldn’t find it in the current context. We can demonstrate this constant lookup using a very basic Ruby program: FOO = "foo"

module Foo class Putter

def self.put

puts FOO end

end end

Foo::Putter.put

With this code, we’ve defined aFOOconstant at the very top level. After that, we’ve defined a module calledFooand a class calledPutter, and that class has a method calledputwhich calls puts FOO. This code will search up the hierarchy, looking for the constant in the Putterclass, then theFoo module and then finally the main namespace.

Go ahead and put this code in a new file and try to run it. We’ll see it outputs “foo”. The constant lookup is working correctly.

(22)

foo-putter.rb:5:in `put': uninitialized constant Foo::Putter::FOO (NameError) from foo-putter.rb:10:in `<main>'

Ruby is telling us here that it cannot find the constant any more, which is true because we commented it out! The most important part of this error message is that it can’t find the constant within theFoo::Putternamespace.

Try now uncommentingFOOand moving the constant to inside themodule Foo, like this:

module Foo FOO = "foo" class Putter

def self.put

puts FOO end

end end

Foo::Putter.put

When we run this code again, we’ll see that it works just the same as if the constant was defined in the main namespace. The code will work also if theFOOconstant is inside the class:

module Foo class Putter

FOO = "foo" def self.put

puts FOO end

end end

Foo::Putter.put

This should demonstrate quite well how constant lookup works within Ruby. Let’s go back to solving our new problem, the “uninitialized constant PostsController::Post” message, armed now with our new knowledge of constant lookup.

Creating the Post model

We need to define aPostconstant within the application for our test to be happy. The best way to do this would be to generate a newPostmodel, which we can do with this command:

(23)

rails g model post

Along with this model comes a migration to create the table. If we attempt to view our application without running this migration, we’ll see this error when we make a request to http://localhost:3000. Migrations are pending;

run 'bin/rake db:migrate RAILS_ENV=development' to resolve this issue.

We can fix this by running the command that it tells us to: bin/rake db:migrate RAILS_ENV=development

We’ll see a similar error when we try to run our automated test,bundle exec rspec spec/features/posts_-spec.rb:

... Migrations are pending;

run 'bin/rake db:migrate RAILS_ENV=test' to resolve this issue.

We can run the recommended command here as well to fix the problem. bin/rake db:migrate RAILS_ENV=test

When we run our test again, we’ll see a different error: Failure/Error: click_link 'New Post'

ActionView::Template::Error:

undefined method `title' for #<Post id: nil, created_at: nil, updated_at: nil> # ./app/views/posts/new.html.erb:4:...

# ./app/views/posts/new.html.erb:1:... # ./spec/features/posts_spec.rb:6:...

We’ve now gotten past the error in our controller and now we’re back to an error within app/views/posts/new.html.erb. While line 1 of this file is mentioned in the stacktrace, it is not the final line and therefore the error is probably not occurring on that line. The very first line of the stacktrace points to line 4, which is this line:

(24)

<%= f.text_field :title %>

The error we’re seeing is happening because somehowtitleis being called on an instance of the Postclass. This is happening because the text_fieldhelper, along with many other form helpers in Rails, will attempt to populate the form with the value from the attribute. It does this by trying to call the attribute’s method. If the attribute’s method is not there, then we see this error happening. What’s happening here is that we didn’t define any columns in thepoststable, which means that there will be notitleorbodyattribute defined for the form to use.

We can fix this by altering the migration for the posts table, which is the only migration in the db/migratefolder. Before we alter it, we need to undo the migration, which we can do by running this command:

bin/rake db:rollback

Now the database is back to its pristine state, we can alter that migration: class CreatePosts < ActiveRecord::Migration

def change create_table :posts do |t| t.string :title t.text :body t.timestamps end end end

Now that the migration is correct, we can run this command to create the table with the correct columns:

bin/rake db:migrate

We need to do the same thing with the test database, and that can be done with this command: bin/rake db:test:prepare

Let’s run that test again and see if everything’s running smoothly: 1 example, 0 failures

Yay! Our test is now passing. The router is receiving the request and passing it to thePostsController. Thenewaction in that controller is defining a @postinstance variable set to a new instance of the Post model. The app/views/posts/new.html.erb template is being run and rendering the form. The form is attempting to fetch the attributes from the newPostmodel instance, but since there are none then the fields will be left blank. All the parts are working in unity and we’ve debugged this bug.

(25)

Rails Example #2 - Routing HTTP verbs/methods

In this example we’ll cover:

• Debugging routing issues • Therake routescommand

This example is very similar to the first example. The changes are that our tests in spec/features/posts_-spec.rbhave now changed to this:

require 'spec_helper' feature "Posts" do

it "can create a new post" do visit "/"

click_link "New Post"

fill_in "Title", :with => "Hello world"

fill_in "Body", :with => "This is the first post." click_button "Create Post"

page.should have_content("Created post.") end

it "can update an existing post" do Post.create({

:title => "Hello world",

:body => "This is the first post." })

visit "/"

click_link "Hello world"

fill_in "Title", :with => "Hello World" click_button "Update Post"

page.should have_content("Updated post.") end

end

When we run the tests using bundle exec rspec spec/features/posts_spec.rb, we’ll see this error:

(26)

1) Posts can update an existing post

Failure/Error: click_button "Update Post" ActionController::RoutingError:

No route matches [POST] "/posts/1" # ./spec/features/posts_spec.rb:21 ...

Let’s mull over this error while we look through the code in the application.

Rather than having a test to ensure that we can see the new post form correctly, the first test now goes through all the motions of creating a new post. It does this by going to the root path of the application and then clicking “New Post”. This routes to thenewaction within thePostsController:

def new

@post = Post.new end

This then renders theapp/views/posts/new.html.erbview which has changed since the last time we saw it:

<h2>Writing a new post</h2>

<%= render "form" %>

The form has been moved into a partial so that it can be used within theeditaction’s template as well. The partial is located atapp/views/posts/_form.html.erband contains this content:

<%= form_for @post, :html => { :method => :post } do |f| %>

<%= f.submit :class => "btn btn-primary" %> <% end %>

For thenewaction, this form will send a request to thecreateaction. For theedit action, we can expect it to send the data to theupdateaction instead because the record represented by@postis persisted within the database.

When this form is submitted from the new template, it will go to the create action within PostsController:

(27)

def create

@post = Post.create(post_params) flash[:notice] = "Created post." redirect_to root_path

end

This simply creates the post from the data posted in and sets a flash notice. We know that all of this is working because the first test withinspec/features/posts_spec.rbis working. It’s the second test which is failing. Let’s look at that failing test again:

it "can update an existing post" do post = Post.create({

:title => "Hello world",

:body => "This is the first post." })

visit "/"

click_link post.title

fill_in "Title", :with => "Hello World" click_button "Update Post"

page.should have_content("Updated post.") end

This test is failing like this:

1) Posts can update an existing post

Failure/Error: click_button "Update Post" ActionController::RoutingError:

No route matches [POST] "/posts/1" # ./spec/features/posts_spec.rb:21 ...

This test first creates a newPostinstance. It then visits the root path, which is a listing of posts. The indexaction withinPostsControlleris responsible for collecting all the posts:

def index

@posts = Post.all end

The template atapp/views/posts/index.html.erbrenders all these posts within a table, showing a link with the post’s title for each post:

(28)

<h2>Posts</h2>

<%= link_to "New Post", new_post_path, :class => "btn btn-primary" %>

<th>Title</th> </thead>

<tbody>

<% @posts.each do |post| %>

<tr>

<% end %>

</tbody> </table>

The test then clicks on the newly created post’s title which takes us to the edit action with PostsController:

def edit

@post = Post.find(params[:id]) end

This action renders the template atapp/views/posts/edit.html.erb: <h2>Editing <%= @post.title %></h2>

This renders the same form partial that we saw earlier used by the template inapp/views/posts/new.html.erb:

After theedittemplate has been rendered, the test edits the title of the post to capitalize the word “world” within the title. It then clicks “Update Post” and that’s where our test is failing. The main part of the error, one more time:

(29)

ActionController::RoutingError: No route matches [POST] "/posts/1" # ./spec/features/posts_spec.rb:21 ...

The stacktrace that follows this isn’t really that helpful because it only shows us the line in the spec which is triggering this problem and doesn’t point to the error in our code so far. We could get a bigger stacktrace by running this command:

bundle exec rspec spec/features/posts_spec.rb -b

But this shows us a lot of Rails and Capybara internal code, and it’s more likely that our code is at fault than Rails’s or Capybara’s. This time, we’re not being pointed in any particular direction and so we need to walk through the steps by ourselves to figure this out.

We know in the test that we’re about to navigate to the root page, and then from there navigate to the edit page and fill in the ‘Title’ field. It’s the clicking the “Update Post” button that is failing, claiming that there is no route defined. We can check the routes defined for the application by running the rake routescommand which will show us this:

Prefix Verb URI Pattern Controller#Action

root GET / posts#index

posts GET /posts(.:format) posts#index

POST /posts(.:format) posts#create

new_post GET /posts/new(.:format) posts#new edit_post GET /posts/:id/edit(.:format) posts#edit post GET /posts/:id(.:format) posts#show

PATCH /posts/:id(.:format) posts#update PUT /posts/:id(.:format) posts#update DELETE /posts/:id(.:format) posts#destroy

This output shows us all routes which are defined within our small application. We want a route that goes to theupdateaction. There are two of these within therake routesoutput:

PATCH /posts/:id(.:format) posts#update PUT /posts/:id(.:format) posts#update

When making a request within Rails, we need to be careful that we use the correct HTTP verb/method. The routes defined for theupdate action use either a PATCHor aPUT request. From the feedback in our test, we can quite clearly see we’re not doing that:

(30)

ActionController::RoutingError: No route matches [POST] "/posts/1" # ./spec/features/posts_spec.rb:21 ...

We’re using POST rather thanPATCHorPUT. Since we know that we can get to the edit action template just fine, let’s start our debugging from there. What we’re looking for is somewhere that is telling the code to make aPOSTrequest rather than aPUTorPATCH. Theapp/views/posts/edit.html.erb template contains this code:

<h2>Editing <%= @post.title %></h2>

This is fairly standard and nothing is standing out here. Let’s look at the partial within app/views/posts/_-form.html.erb:

On the very first line here is where we’re explictly telling the code to use the POST verb rather than PUT or PATCH. If we change this to useputorpatch, like this:

<%= form_for @post, :html => { :method => :put } do |f| %>

Or:

<%= form_for @post, :html => { :method => :patch } do |f| %>

Then run our tests withbundle exec rspec spec/features/posts_spec.rb, we’ll see our first test is now failing with a similar reason:

(31)

1) Posts can create a new post

Failure/Error: click_button "Create Post" ActionController::RoutingError:

No route matches [PATCH] "/posts" # ./spec/features/posts_spec.rb:9 ...

Doomed if you do, doomed if you don’t. What we’re failing to realise here at this point is that form_forautomatically takes care of using the right HTTP verb/method. We don’t actually need

to specify the method. Let’s remove that option from theform_fornow, leaving that first line like this:

<%= form_for @post do |f| %>

When we run our tests again, they will now pass: 2 examples, 0 failures

The issue all along was that we were explicitly specifying the HTTP verb/method for the form, but we didn’t need to do that because Rails deals with this automatically. Rails does this by checking thepersisted?method’s return value. This method returnstrueif the object is represented in the database with a record in the table, orfalseif not. Let’s go into therails consolenow and see what this does.

When we try that method with a newPostobject, we’ll get this:

irb(main):001:0> post = Post.new

=> #<Post id: nil, title: nil, body: nil, created_at: nil, updated_at: nil> irb(main):002:0> post.persisted?

=> false

If we try it with aPostobject that’s fetched from the database, we’ll get this:

irb(main):001:0> post = Post.create

=> #<Post id: 1, title: nil, body: nil, created_at: nil, updated_at: nil> irb(main):002:0> post.persisted?

=> true

If the return value of thispersisted?method isfalse, theform_forhelper will route to the plural name of the resource usingposts_pathin this case. It will also use thePOSTHTTP verb/method. If the return value of the method istrue, then it will route to the singular name of the resource using post_path(post), using thePATCHHTTP verb/method.

(32)

Debugging slow code

Without proper care, applications can get slow over time. Pages that once loaded quickly can degrade into taking more than a second to load. This can be caused by a slow database lookup, too many database lookups or just even too much information displayed on the page at any particular time. Slowness within an application can almost be called a “bug” itself. It’s definitely not a feature! In this chapter, we’ll cover some common pitfalls that people can inadvertently stumble upon during Rails application development. You might even be surprised at how easy some of the fixes are.

Rails Example #4 - Reducing Repeated Queries

In this section we’ll cover: • Includes queries • Pagination

This example app is a slight modifications on the earlier blogging application. In this application, we have aPostmodel whichhas_many :comments, and thatCommentmodelhas_many :users. Before we start this application, we’re going to need to run this command to set up some test data:

rake db:seed

All this task will do is run the code within the db/seeds.rb file within the context of our Rails application’s development environment. This code looks like this:

post = Post.create(:title => "Hello World", :body => "This is the first post.") users = 5.times.map do

User.create(:name => "User#{rand(9999)}") end

1000.times do Comment.create(

:post => post,

:user => users[rand(5)],

:body => "This is just a comment." )

end

This code creates a single post, then 5 randomly numbered users, then 1000 comments with the same post and text, but a randomly chosen user for each comment. Let’s look at what this data makes our application do by firing up the Rails server:

(33)

rails s

Going to http://localhost:3000 will show us the familiar list of posts:

Posts

Clicking on this post’s link will now show us the post itself, along with a whole bunch of comments:

Posts

Your numbers will probably⁸be different, but that’s alright. If we switch over to the terminal session whererails sis running, we’ll see a quite large amount of queries that are being run to load our data:

Processing by PostsController#show as HTML Parameters: {"id"=>"1"}

Post Load (0.1ms) SELECT "posts".* FROM "posts" ...

Comment Load (2.8ms) SELECT "comments".* FROM "comments" ... User Load (0.2ms) SELECT "users".* FROM "users" ...

CACHE (0.0ms) SELECT "users".* FROM "users" ... User Load (0.2ms) SELECT "users".* FROM "users" ... CACHE (0.0ms) SELECT "users".* FROM "users" ...

At the top of this mountain of queries is the query to load the post. This needs to happen, otherwise we would not be able to show the post’s data. The second query is one to load the comments, which runs for a similar reason: we need to show the comments. The 1000 queries (don’t count them) that follow are loading all the users for the comments. But why are there 1000 queries when there’s only 5 users to load? Because Rails doesn’t know any better. Luckily for us though, Active Record is caching the results of these queries and fetching the back from the cache when it goes to run that query again. These lines in the output begin withCACHE.

At the end of the output, we’ll see this:

The entire action is taking 681ms to render, 655ms of that is within the view and 18.4ms is happening within Active Record. A lot of this slowness is due to the number of queries and query cache hits that Rails is undergoing during this request.

⁸Interesting trivia fact: The probability of the numbers not being different is 1 in 10000 to the power of 5, or 1 in 100 quintrillion (1 in 100,000,000,000,000,000,000).

(34)

When any action within our application runs, we should try and minimize the database querying needed for that action. Even a single query takes time, and so ideally we would like to reduce it down to 0 queries. Let’s not go all the way to that extreme yet. We should focus our efforts on making Active Record stop performing 1000 lookups for these users.

The way we can fix this problem is with something in Active Record called eager loading. Eager loading will load the required data in as few queries as possible. We can use this within theshow action of thePostsControllerlike this:

def show

@post = Post.includes(comments: :user).find(params[:id]) end

The includesstatement here triggers eager loading for this query. The Hash object passed as the argument to this tells Active Record to eager load thecommentsassociation from thePostmodel, as well as theuserassociation for each comment.

When we reload the page in our browser and look at the queries again, there’s no longer over a thousand of them:

Started GET "/posts/1" for 127.0.0.1 at 2013-11-24 11:52:14 +1100 Processing by PostsController#show as HTML

Parameters: {"id"=>"1"}

... SELECT "posts".* FROM "posts"

WHERE "posts"."id" = ? LIMIT 1 [["id", "1"]] ... SELECT "comments".* FROM "comments"

WHERE "comments"."post_id" IN (1) ... SELECT "users".* FROM "users"

WHERE "users"."id" IN (1, 3, 2, 5, 4)

There are now only 3 queries for the data that needs to be displayed on this page: one for the post, one for the comments and one for all the users for all the comments. The eager loading here has altered the query for the comments to load it using anINquery, rather than the query it ran before:

... SELECT "comments".* FROM "comments"

WHERE "comments"."post_id" = ? [["post_id", 1]]

This doesn’t make too much of a different in the query speeds. The two queries are going to produce the same result. The major difference here is that the 1000 queries for the users for the comments has now been reduced to one simple query:

(35)

... SELECT "users".* FROM "users"

WHERE "users"."id" IN (1, 3, 2, 5, 4)

We can also see that the page which once took around 700ms to load (650ms in the view, 25ms in Active Record), is now loading much, much faster:

The page is now loading seven times faster with this one easy trick. That’s great!

TODO

• Pagination

• Fragment caching

(36)

Not all exceptions known to humankind have been documented in this book so far. There will be more than these which pop up in the applications that you will write. By default, when users cause an exception to happen within a Rails application, this is what they’ll see:

500 Error Page

Exceptions will happen in your applications, because nobody writes perfect code. Sometimes these exceptions might happen under a set of very, very specific circumstances and only for one user. Unless that user contacts you specifically, you may never know that this exception is happening. That’s where exception notification services come into play. These range from the basic exception_-notification gem (http://smartinez87.github.io/exception_exception_-notification/) which you can install and configure to email you whenever an exception happens, all the way up to the large scale New Relic which does much much more than exception notifications. There are others too, such as Airbrake (http://airbrake.io) and Honeybadger (honeybadger.io).

(37)

Advanced Rails Example #1 - Broken Devise

Application

This example was from a debugging session I did with Steven Baker on November 25th, 2013.

In this example we’ll cover: • bundle show

• Debugging with the pry gem

• How to find where methods are defined

Not all applications that we debug are going to be on the latest and greatest versions of everything. Sometimes we’ll be asked to debug code that is years old and more often than not written by somebody else. Unfamiliarity with an older version of Rails or another gem may seem like a huge hurdle at first, but on closer inspection that hurdle is a lot smaller than it seems.

Debugging sometimes requires a large amount of patience and concentration, as this (almost 5,000 word) example shows. The pay off at the end of such a long debugging session is worth it, in my opinion. I get a little kick out of it. Let’s start debugging.

Here in this application, we are having a problem where (imaginary) users are unable to sign in. The (imaginary) user is reportedly seeing a 500 error page when they try to sign in, which is indicative of a bigger problem. Thankfully another (imaginary) developer within this aplication has written a test to cover this breakage using RSpec + Capybara. This test lives atspec/features/sign_in_spec.rb: require 'spec_helper'

describe "sign in" do before do

User.create!(:email => "[email protected]", :password => "password") end

it "can sign in successfully" do visit "/"

click_link "Sign in"

fill_in "Email", :with => "[email protected]" fill_in "Password", :with => "password" click_button "Sign in"

page.should have_content("Signed in successfully.") end

(38)

When we run this test usingbundle exec rspec spec/features/sign_in_spec.rb, we’ll see that it is indeed breaking:

1) sign in can sign in successfully Failure/Error: click_button "Sign in" ActionController::RoutingError:

uninitialized constant SessionsController # ./spec/features/sign_in_spec.rb:13...

It says “uninitialized constant SessionsController”, but Devise should be handling the authentication, shouldn’t it? Devise has a controller within its own code called Devise::SessionsController which should be handling this request, but for some reason it is not. It’s trying to use the SessionsControllerwithout theDevisenamespace.

Running the test with bundle exec rspec spec/features/sign_in_spec.rb -byields no better information, showing us only stacktrace from within Rails or Rack.

Let’s investigate this problem ourselves by starting up this application now: rails server

If we now go to http://localhost:3000 and click “Sign in”, we’ll see the standard Devise form consisting of an email and password field.

Sign in form

If we attempt to sign in with “[email protected]” and “password”, it will fail and show the same error that we saw from our tests:

(39)

Routing error for SessionsController

Why is this happening? The path for this request looks weird. It shows as “localhost:3000/session.user”. Where is that coming from? The best first place to look would be back on the sign in page itself to see if the form tag is sending us there. If we go back to that page, right click on an element of the form and click “Inspect Element”, we’ll see that the form’s HTML makeup begins with this:

This explains how we’re being taken to/session.user, but not the why. Let’s investigate how Devise generates that form now. The template that displays this form lives inside the Devise gem rather than our application. To get to the template, we’re going to need to open the current version of Devise that the application is using. To get there, we’re going to need to find where Devise is installed on our system. Lucky for us, there’s a command to do that:

bundle show devise

This command will show the path to the gem that the application’s Gemfile will use when it sources its dependencies. It will show something like this:

/Users/user/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/devise-1.1.9

We can open this path in our editor by running this command: $EDITOR `bundle show devise`

If that doesn’t work, then you will need to open the path manually in your editor.

Now that we have Devise open, we need to figure out what template is being shown that renders this form. We can find that out by looking at the log output from ourrails serversession when a request to the sign in page is made:

(40)

Started GET "/users/sign_in" for 127.0.0.1 ...

Processing by Devise::SessionsController#new as HTML

Rendered .../devise-1.1.9/app/views/devise/shared/_links.erb (0.9ms) Rendered .../devise-1.1.9/app/views/devise/sessions/new.html.erb

within layouts/application (5.6ms)

In this output, we can see that we’re making a request to/users/sign_inand that request is being routed to thenewaction withinDevise::SessionsController. This action then goes on to render a couple of templates, namely devise/shared/_links.erb and devise/sessions/new.html.erb. The code for the form is probably going to be in thesessions/new.html.erbtemplate. Inside that template we’ll see this code to generate the form:

<%= form_for(resource,

:as => resource_name,

:url => session_path(resource_name)) do |f| %>

For the URL of the form, thisform_forcall is calling thesession_pathhelper, which is probably a routing helper. We can find out where this is defined within our application by running this command:

rake routes

This command will show this output for this application:

root /(.:format) ...

new_user_session GET /users/sign_in(.:format) ... user_session POST /users/sign_in(.:format) ... destroy_user_session GET /users/sign_out(.:format) ... user_password POST /users/password(.:format) ... new_user_password GET /users/password/new(.:format) ... edit_user_password GET /users/password/edit(.:format) ...

PUT /users/password(.:format) ...

user_registration POST /users(.:format) ...

new_user_registration GET /users/sign_up(.:format) ... edit_user_registration GET /users/edit(.:format) ...

PUT /users(.:format) ...

DELETE /users(.:format) ...

session POST /session(.:format) ...

new_session GET /session/new(.:format) ... edit_session GET /session/edit(.:format) ...

GET /session(.:format) ...

PUT /session(.:format) ...

(41)

On the left-hand side of this output, we can see the path helpers defined for the routes if they are present. We can see that there is one line in particular that defines asessionhelper:

session POST /session(.:format)

{:action=>"create", :controller=>"sessions"}

This is the helper that is being used by Devise to generate the route for the form incorrectly. Where is this coming from though? Let’s look inconfig/routes.rband see if anything there sticks out:

Bug::Application.routes.draw do root :to => "welcome#index" devise_for :users

resource :session

end

At the very bottom of this file there is a resource :session line, which is what is defining the session_path helper. Since there is no SessionsController for this route to use within the application, it probably got left over in this application from a previous developer. Let’s remove this line fromconfig/routes.rbnow:

resource :session

For this route change to take full-effect, we’ll need to restart ourrails serversession so that the session_pathhelper is completely forgotten about. Once we’ve restartedrails server, we can try to sign in again with “[email protected]” and “password”. This time we’ll see a completely different error message:

(42)

Ok, a different error message is progress because it means something new is happening! First thing to check: is there actually a user with the email address “[email protected]” within the database? The easiest way to check that would be to launch a new console session:

rails c

Within this console session, we want to find if a user with the email “[email protected]” exists, which we can do like this:

User.exists?(:email => "[email protected]") When we run this code, we’ll see that it doesn’t exist:

irb(main):001:0> User.exists?(:email => "[email protected]") => false

This is happening because the only place where we have been creating this user is within the test environment, and not the development environment. These two environments use separate databases and after a test is run within the test environment, that database is emptied anyway. Therefore this problem may be caused by a simple case of a missing user. Let’s create this new user in the database now:

User.create!(:email => "[email protected]", :password => "password") With this user created, we can try to sign in again.

(43)

Unfortunately, that did not fix the problem yet. The error message is still telling us invalid email and password, although we’re pretty certain that it’s the right email address and the right password. We can double-check this by first finding the user in the console:

>> user = User.find_by_email("[email protected]") => #<User id: 1 ...>

With this, we can see that the user does actually exist. Now let’s check to see if the password is valid using Devise’svalid_password?method:

>> user.valid_password?("password") => true

The user definitely exists and their password is definitely valid, even though the error message is telling us that this is not true. The error message is lying to us. Let’s take a look at the logs which may give us more leads as to where to look to figure this one out.

Here’s what happening for this request:

Started POST "/users/sign_in" for 127.0.0.1 at 2013-11-27 18:03:40 +1100 Processing by Devise::SessionsController#create as HTML Parameters: ... Completed in 4ms Processing by Devise::SessionsController#new as HTML Parameters: ... Rendered .../app/views/devise/shared/_links.erb (0.8ms)

Rendered .../app/views/devise/sessions/new.html.erb within layouts/application (\ 5.0ms)

Completed 200 OK in 97ms ...

We can see here that Rails is receiving the request from the sign in form and that the request is being handled by thecreateaction withinDevise::SessionsController. Somehow, the action does not respond in any particular fashion, indicated with the “Completed in 4ms” message. Typically we would expect to see a “200 OK” or “302 Redirected” message there, but we’re not seeing that. After this action complese, thenewaction within the same controller gets the same parameters and then re-renders theapp/views/devise/sessions/new.html.erbtemplate.

To begin to discover what’s happening here, let’s check out the code withinDevise::SessionsController. If the gem is not open any more, re-open it using this command:

$EDITOR `bundle show devise`

Within Devise, this controller is located atapp/controllers/devise/sessions_controller.rband itscreateaction looks like this:

(44)

devise/app/controllers/devise/sessions_controller.rb 1 def create

2 resource = warden.authenticate!(:scope => resource_name, :recall => "new") 3 set_flash_message :notice, :signed_in

4 sign_in_and_redirect(resource_name, resource)

5 end

Thecreateaction first calls out to thewardenmethod which is provided by the Warden gem which Devise depends on. Thewardenmethod is a proxy object which keeps track of the current session state. We can find out where theauthenticate!method for this proxy object is defined by firstly adding theprygem to our ‘Gemfile:

gem 'pry'

We can install this gem usingbundle install. This gem provides us with some useful debugging tools which we’ll see used as we go along. The first of these is the breakpoint helper called binding.pry. This stops code execution right in its tracks and will bring up an IRB-esque prompt which we can then use to debug code. We’re going to use this within the create action in Devise::SessionsControllerlike this:

devise/app/controllers/devise/sessions_controller.rb 1 def create

2 binding.pry

3 resource = warden.authenticate!(:scope => resource_name, :recall => "new") 4 set_flash_message :notice, :signed_in

5 sign_in_and_redirect(resource_name, resource)

6 end

To ensure that our server has this latest and greatest code, we’ll need to restart it. Once it’s been restarted, if we try signing in again the browser should hang and then in the server window we’ll see the Pry prompt:

12: def create

=> 13: binding.pry

14: resource = warden.authenticate!(:scope => resource_name, :recall => "new") 15: set_flash_message :notice, :signed_in

16: sign_in_and_redirect(resource_name, resource) 17: end

We can treat this prompt just like any other Ruby prompt. We can call whatever Ruby code we wish within it. Right now though, all we want to know is where theauthenticate!method is defined. Let’s find that out now by using this code: