While optimizing our Rails apps, I used the standard Rails Logger to output performance information about specific trouble-spots of code. Having to constantly grep through the production log, however, was driving me nuts. What I really wanted to do was to write information about a specific problem area to a specific file, without adding a lot of extra code.

And now the LogCabin Rails plugin makes this very easy (Get it on GitHub).

The LogCabin plugin is designed to give you the flexibility to write information about blocks of code and their execution times to specific log files in your Rails project. LogCabin can also be used in Rake tasks, which can be incredibly helpful for debugging and monitoring long-running tasks.

Example Usage

This is especially useful when monitoring and debugging a specific set of code in a model or controller file. As a contrived example:

class UsersController < ApplicationController
  def index
    LogCabin.log_to :user_search do |log|
      log.debug "Finding all users with params = '#{params[:user_search].map{|k,v| "#{k}: #{v}"}.join(', ')}'"
      @users = User.search(params[:user_search])
      log.info "Found a total of #{@users.length} users"
      log.warn "ONLY FOUND #{@users.length} USERS" if @users.length < 50
    end
  end
end

LogCabin logs the time it took to run the block, along with any info, debug or warn messages that you ran on the log object. This code might print the following out to RAILS_ROOT/log/user_search.log:

DEBUG: Finding all users with params = 'last_name: Smith, city: Chicago'
INFO: Found a total of 32 users
WARN: ONLY FOUND 32 USERS
TIME: Tue Nov 18 12:34:52 -0600 2008: Operation took 3.2876 seconds

It is also possible to pass an :if or :unless option to LogCabin#log_to, ex:

LogCabin.log_to :users_query, :if => RAILS_ENV == 'development' do |log|
  log.info "This will not output anything unless we're in development"
  puts "But any other Ruby code in this block will always be run"
end

Leveraging Capistrano

I think one of the best parts about using LogCabin is how easy it is to check up on these logs across multiple production servers using Capistrano. Here's a cap task that will let you tail a specific log or monitor the live stream:

# Assumes the deploy_to variable has been set in your Capistrano config
namespace :deploy do
  namespace :log do
    desc "Tails a log "
    task :tail, :roles => [:app] do
      set(:log_name) do
        Capistrano::CLI.ui.ask "Which log do you want to fetch? "
      end
      set(:line_count) do
        Capistrano::CLI.ui.ask "How many lines should I fetch? (blank to tail log) "
      end
      if line_count.strip! =~ /^\d+$/
        run "tail -n #{line_count} #{deploy_to}/current/log/#{log_name.gsub(/\.log$/, '')}.log"
      else
        run "tail -f #{deploy_to}/current/log/#{log_name.gsub(/\.log$/, '')}.log"
      end
    end
  end
end

Download LogCabin from GitHub

When I was small, I remember wondering if people see colors the same way. Do you see blue like I see purple? Is your mustard my marigold? Why are you wearing neon green when it is so clearly a distracting and heinous hue? Furthermore, what does the world look like through colorblind eyes? In a year in which color is such a politically provocative and empowering idea, I wanted to reflect a bit on how it inspires me.

I won't delve into color theory, as there are many designers speaking on the subject who are far more knowledgeable and eloquent than me. And honestly, I'm most often more attracted to a lack of color than vibrant ones — I'm in constant search of the perfect shade of grey (I just can't get enough charcoals and slates and taupes) — so I'm certainly no expert in the ways of color. But every so often, I'll see a combination of colors that just knock my socks off, and it's rarely the overtly bold and bright colors, but the unexpected, the clashing, the subtle.

One of my favorite artists is Mark Rothko, whose highly abstract use of color evokes emotions and energies that transcend the color themselves. "The people who weep before my pictures," he has said, "are having the same religious experience I had when I painted them. And if you say you are moved only by their color relationship, then you miss the point." For him, the relationships between colors and the emotions they evoke make for a spiritual experience, and I can't disagree. Standing in front of a Rothko in a museum, it feels a bit disrespectful to do anything but stare in stunned silence.

In contrast, Gerhardt Richter, Ellsworth Kelly, and other minimalist artists often used the idea of a commercial color chart or paint color chips and subvert them to show the purely visual, objective, and consumerist nature of color. This idea of randomness, of found color, can be very inspirational. I recently received a Color Accordion as a gift, and flipping through the deck makes this monochromatic-loving gal want to add some color to her life. Check out the paint section of your local hardware store (which I've been to a few times lately... 50 shades of white... how do I choose?), and see if you're not inspired by the rainbow of hues and subtle fades.

But most of all, I like to see color through a camera lens, because sometimes photographs can show beauty that we don't notice in our hustle and bustle lifestyles. With a full memory card and a handy Photoshop eyedropper tool, it's amazing what hidden color ways you can find, even in the most mundane of scenes. It's instant color inspiration for art, design, and spicing up the digs. Furthermore, it can be applied conceptually — how relevant would it be to apply a color way from a photograph of a Japanese fish market to a website for a new sushi restaurant in Lakeview? Sure it's a stretch, and no one but you will know the inspiration, but it's a good way to step outside your usual go-to schemes.

Nowadays I've come to the conclusion that we don't all see colors in the same way, although I can't say whether it comes down to matters of taste or perception. But it's clear that colors have the power to evoke emotion. Our marketing manager tells me that in 2009, the 'new black' will be yellow, a color representing hope, sunshine, and warmth. It's a happy thought, one that will support the big changes we hope to see in the year to come. And, thankfully, yellow looks great with grey.

In my previous article we took a Behavior Driven Development approach to testing our data layer, in which our models were tested using RSpec. In this article I will showcase how RSpec can be used for controller testing. If you are new with RSpec, I will not go into detail with basic RSpec syntax such as should and it, please read my previous article, TDD, BDD and Using RSpec which goes over the basics to get you started.

Before we dive into controller testing, let's quickly create our app that will help birdkeepers find information on birds. Run the following commands:

rails birdkeeper -d mysql
cd birdkeeper
script/generate scaffold Bird title:string species_id:integer notes:text

Create birdkeeper_development and birdkeeper_test databases, add your database credentials to config/database.yml and migrate:

rake db:migrate
rake db:migrate RAILS_ENV=test

Then add the RSpec plugins (through git), gem (if not installed) and generate the spec directories:

sudo gem install rspec
script/plugin install git://github.com/dchelimsky/rspec.git
script/plugin install git://github.com/dchelimsky/rspec-rails.git
script/generate rspec

Open up app/controllers/birds_controller.rb, it should contain the 7 CRUD actions created from the Rails scaffold generator. If there are no actions, your version of Rails may need to be updated. Create birds_controller_spec.rb inside of spec/controllers. Add the following code:

require File.expand_path(File.dirname(__FILE__) + '/../spec_helper')

describe BirdsController do

end

The first line loads in the spec_helper file which will contain common code that can be shared between specs. Next we have a describe block which helps keep our tests organized. This one will contain tests relating to the BirdsController, which will hold all our tests. It will also contain inner describe blocks for further organization. Let's test the update method, since in addition to performing a find call like most CRUD actions, it also updates the object. The update method we will be using is as follows:

# PUT /birds/1
# PUT /birds/1.xml
def update
  @bird = Bird.find(params[:id])

  respond_to do |format|
    if @bird.update_attributes(params[:bird])
      flash[:notice] = 'Bird was successfully updated.'
      format.html { redirect_to(@bird) }
      format.xml  { head :ok }
    else
      format.html { render :action => "edit" }
      format.xml  { render :xml => @bird.errors, :status => :unprocessable_entity }
    end
  end
end

Go back to the BirdsController spec and add the following inside of the BirdsController describe block:

# UPDATE
describe "PUT birds/:id" do
    describe "with valid params" do
    
    end
    
    describe "with invalid params" do
    
    end
end

Above we have added 3 describe blocks. One wrapper describe block will contain all tests relating to the update method. Inside there are two describe blocks, one with tests if valid params are given and the other if invalid params are given. Let's start with valid parameters. Before writing the actual tests, we need to set expectations. This is done through mocking and stubbing within a before block. Add the following inside the "with valid params" describe block:

before(:each) do
    @bird = mock_model(Bird)
    Bird.stub!(:find).with("1").and_return(@bird)
end

The before block will run before each test. This will DRY up our tests since we won't have to rewrite the same mocks and stubs for each test. Mocks and stubs allow us to test the controller functionality without relying on ActiveRecord. With mock_model we are imitating a Bird object. Stubs are used to fake method calls, we don't need to know the details of the actual method. We just know that the Bird class will receive a find call with a argument of "1" and it should successfully return a @bird object, which will be our mock. Then later in the same method, the @bird mock will receive an update_attributes call, so we also need to stub this call out. We can stub it out as follows:

@bird.stub!(:update_attributes).and_return(true)

But there is another way to accomplish this much more DRYly. Our mock model accepts a optional hash of method calls and their return value. We can modify our @bird mock object into:

@bird = mock_model(Bird, :update_attributes => true)

With the before block set up we can start writing tests. Tests are contained in it blocks and takes a string argument explaining its contents. Let's first test the find call, which is the first action to happen after update is called.

it "should find bird and return object" do
    Bird.should_receive(:find).with("1").and_return(@bird)
    put :update, :id => "1", :bird => {}
end

Here we are testing if the Bird class received a find call, with the should_receive syntax. The rest is very similar to the stub method since we are checking if it received "1" as an argument and returned a @bird object.

After a Bird object is found, its attributes are updated. Testing this call is very similar to the find call:

it "should update the bird object's attributes" do
    @bird.should_receive(:update_attributes).and_return(true)
    put :update, :id => "1", :bird => {}
end

Next we make sure a flash notice is set:

it "should have a flash notice" do
    put :update, :id => "1", :bird => {}
    flash[:notice].should_not be_blank
end

If the controller can have one of many flash notices, we can also be more specific:

it "should have a successful flash notice" do
    put :update, :id => "1", :bird => {}
    flash[:notice].should eql 'Bird was successfully updated.'
end

After the flash notice is set, the user should get redirected to the bird's show page. We can test the redirect by accessing the response object as so:

it "should redirect to the bird's show page" do
    put :update, :id => "1", :bird => {}
    response.should redirect_to(bird_url(@bird))
end

As for testing if there was invalid data, we would do this:

before(:each) do
    @bird = mock_model(Bird, :update_attributes => false)
    Bird.stub!(:find).with("1").and_return(@bird)
end

it "should find bird and return object" do
    Bird.should_receive(:find).with("1").and_return(@bird)
    put :update, :id => "1", :bird => {}
end

it "should update the bird object's attributes" do
    @bird.should_receive(:update_attributes).and_return(false)
    put :update, :id => "1", :bird => {}
end

it "should render the edit form" do
    put :update, :id => "1", :bird => {}
    response.should render_template('edit')
end

Most is similar to the valid data version, but there are a few differences. We are stubbing the object's update_attributes call to return false, this will cause the conditional to take the else route. Since there are errors, it needs to render the edit page. We test this by doing a response.should render_template('edit').

This is how the complete Bird Controller spec looks:

require File.expand_path(File.dirname(__FILE__) + '/../spec_helper')

describe BirdsController do

  # UPDATE
  describe "PUT birds/:id" do

    describe "with valid params" do
      before(:each) do
        @bird = mock_model(Bird, :update_attributes => true)
        Bird.stub!(:find).with("1").and_return(@bird)
      end
      
      it "should find bird and return object" do
        Bird.should_receive(:find).with("1").return(@bird)
      end
      
      it "should update the bird object's attributes" do
        @bird.should_receive(:update_attributes).and_return(true)
      end
      
      it "should redirect to the bird's show page" do
        response.should redirect_to(bird_url(@bird))
      end
    end

    describe "with invalid params" do
      before(:each) do
        @bird = mock_model(Bird, :update_attributes => false)
        Bird.stub!(:find).with("1").and_return(@bird)
      end

      it "should find bird and return object" do
        Bird.should_receive(:find).with("1").return(@bird)
      end

      it "should update the bird object's attributes" do
        @bird.should_receive(:update_attributes).and_return(false)
      end

      it "should render the edit form" do
        response.should render_template('edit')
      end
      
      it "should have a flash notice" do
        flash[:notice].should_not be_blank
      end
    end
    
  end
end

Run this spec from the root of your application with the following command, all specs will pass:

ruby spec/controllers/birds_controller_spec.rb

Using the information learned here can be applied to writing tests for the other 6 CRUD actions. Since these actions were generated through the Rails scaffold generator, they should work and tests may not be needed. On the other hand, changes in functionality may cause new bugs to pop up. It is recommended to write tests and cover as much possible. It may become tedious to write tests for basic CRUD actions for each generated controller, luckily RSpec has a scaffold generator that will generate the same files complete with RSpec tests. The RSpec version of the scaffold can be used as follows:

script/generate rspec_scaffold Bird title:string species_id:integer notes:text

As a bonus, let's say we created a Species scaffold. A bird will belong to Species and we have the Birds controller nested within the Species controller. On the Species show page, we would run the following find methods for a list of birds that belong to that Species. Just how should the following be mock and stubbed?

@species = Species.find("1")
@birds_in_species = @species.birds.find(:all)

Take a few minutes to think about it. It is a bit more complicated, but like any complicated matter, can be simplified by breaking it down. I start off by mocking all objects involved, @species and @birds_in_species are a given. But we also can't forget the birds that are going to be returned from @species.birds, that needs to be mocked as well.

@birds_in_species = mock_model(Bird)
@species = mock_model(Species)
@birds = mock_model(Bird)

As for stubbing out the method calls. There are three in total, @species.birds.find counts as two.

Species.stub!(:find).with("1").and_return(@species)
@species.stub!(:birds).and_return(@birds)
@birds.stub!(:find).and_return(@birds_in_species)

Then in our tests, we would do the following:

Species.should_receive(:find).with("1").and_return(@species)
@species.birds.should_receive(:find).and_return(@birds_in_species)

I hope you have found this article helpful on testing controllers with RSpec. If you have checked out the generated specs through the rspec_scaffold generator, there are less tests for the update method. I prefer to have many smaller tests with each testing a small portion of the controller, that way when a single line is changed, the error from the test will be more helpful since it is more specific. I have found out about this approach from Mike Mangino, though ultimately how your specs are organized is a matter of personal preference.