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

This is the third article in a series about best practices for creating Rails forms. Be sure to check out Pretty Data, Pretty Code and Modeling All Form Data for more related techniques.

Revisiting Our Form

Continuing with the example from my last article, I have this simple form:

<% form_for :product, :url => products_path do |f| %>
  <div class="form_item text_field">
    <label for="product[name]">Name:</label>
    <%= f.text_field :name %>
  </div>
  <div class="form_item text_field">
    <label for="product[price]">Price:</label>
    <%= f.text_field :price %>
  </div>
  <div class="form_item text_field">
    <label for="product[features]">Features (1 per line):</label>
    <%= f.text_area :features %>
  </div>
  <div class="form_item submit_button">
    <%= f.submit "Create Product" %>
  </div>
<% end %>

Note: I changed the original form's wrapper tags from <p> to <div>. The reason is that, if you're using the built-in Rails error message helpers, by default it will wrap erroneous fields in <div> tags. Since <div> tags can't nest within <p> tags, this can cause serious layout-breaking problems.

There's a lot of duplication here in terms of the wrapper code. Each field is wrapped in a <div> with a class of form_item as well as a descriptor of what kind of field it contains. I use this information for CSS styling of specific kinds of inputs. The labels are also fairly repetitive as well, and these repetitions would become more obnoxious were this a longer form.

Removing Repetition

What if we could generate this same form code while removing the repetition? It's possible, and Rails gives us a great hook for just this scenario by allowing us to build custom Form Builders. A custom Form Builder is simply a subclass of ActionView::Helpers::FormBuilder that can alter and extend the abilities of the regular Form Builder. In our current form, the f block variable is an instance of FormBuilder, so methods like text_field and submit are all instance methods of the FormBuilder class. Let's override these methods to not only output the field markup, but to also output the wrapper div:

# in /helpers/application_helper.rb
class WrapperFormBuilder < ActionView::Helpers::FormBuilder
  METHODS_TO_OVERRIDE = %w{text_field text_area password_field file_field date_select datetime_select submit}

  METHODS_TO_OVERRIDE.each do |method_name|
    src =<<END_SRC
      def #{method_name}_with_wrapper(field, options={})
        # allow explicit setting of label text with options[:label]
        field_label = if '#{method_name}' == 'submit'
          '' # no label for submit inputs
        elsif options[:label]
          label(field, options.delete(:label))
        else
          label(field) + ":" # Adds colon as default
        end

        # get unwrapped field
        field_markup = #{method_name}_without_wrapper(field, options)

        # return wrapped field (@template gives us access to helper methods in this class)
        @template.content_tag(:div, field_label + field_markup, :class => "form_item #{method_name}")
      end
    END_SRC
    class_eval src, __FILE__, __LINE__
    alias_method_chain method_name.to_sym, :wrapper
  end

end

For our form, we can now implement our new class like this:

<% form_for :product, :url => products_path, :builder => WrapperFormBuilder do |f| %>

Another possibility is to create a new method to replace form_for:

# in helpers/application_helper.rb
def wrapper_form_for(name, object=nil, options={}, &proc)
  form_for(name, object, options.merge(:builder => WrapperFormBuilder), &proc)
end

Using this new helper method, our form now looks like this:

<% wrapper_form_for :product, :url => products_path do |f| %>
  <%= f.text_field :name %>
  <%= f.text_field :price %>
  <%= f.text_area :features, :label => "Features (1 per line):" %>
  <%= f.submit "Create Product" %>
<% end %>

If you need to create a form field without a wrapper (perhaps to use a non-conforming wrapper), you can still access the original methods like f.text_field_without_wrapper or f.submit_without_wrapper.

I have found custom Form Builders to be powerful tools for speeding up form development, DRYing up code and keeping consistency between forms and developers. This is a fairly basic example, but the sky is the limit for what you can implement using these techniques.

In my last article I wrote about using data modeling to clean up form-related code and to take advantage of powerful helpers like form_for and error_messages_for. This solves the significant problem of isolating business logic into a model class, but another problem remains — how can we make our form data pretty without trashing our model's code with view logic?

Beautifying the Data

I have a simple Product model with rows for name, price and features. Setting and displaying the price field is tricky because I need to remove currency formatting before storing it in the database as a decimal, and I want to reformat it when displaying the current price in an 'Edit' form. The features field is also tricky. I want the user to enter each product feature ("Slices and Dices", "Purees Anything", etc.) on a separate line of the textarea and for that to be split into a serialized array that I will store in the database.

My first instinct is to create virtual attributes in my model to handle the logic of deformatting/reformatting this data. Here's how it looks:

class Product < ActiveRecord::Base
  serialize :features, Array
  
  validates_presence_of :name
  validates_numericality_of :price
  
  # need this for formatting
  def helpers
    ActionController::Base.helpers
  end
  
  def price_field=(p)
    # expecting p to be something like "$4,000.00", set price to 4000.00
    p.gsub!(/[^0-9.]/, '')
    self.price = p.to_f
  end
  
  def price_field
    helpers.number_to_currency(self.price)
  end
  
  def features_field=(str)
    # expecting string with features separated by newlines
    self.features = str.split("\n").collect {|f| f.strip }
  end
  
  def features_field
    self.features.join("\n")
  end
end

<%# the product form %>
<% form_for :product, url => products_path do |f| %>
  <p class="form_item text_field">
    <label for="product[name]">Name:</label>
    <%= f.text_field :name %>
  </p>
  <p class="form_item text_field">
    <label for="product[price_field]">Price:</label>
    <%= f.text_field :price_field %>
  </p>
  <p class="form_item text_field">
    <label for="product[features_field]">Features (1 per line):</label>
    <%= f.text_area :features_field %>
  </p>
  <p class="form_item submit_button">
    <%= f.submit "Create Product" %>
  </p>
<% end %>

The good news is that we have a very simple, straightforward looking view with no logic stuffed in it. Our controller is also completely vanilla, so I didn't bother to even show it.

Our model, however, is getting cluttered. What once was a haven for business logic is now filled with both business and view logic. I'm also a little concerned about having to use the #price_field and #features_field methods, since it adds complexity to what should be a simple object API. Will this cause confusion with my fellow programmers?

Beautifying the Code

What if we extracted the view logic into its own object? By using a presenter object as an adapter between our Product model and our form we can isolate the view logic from the business logic. Here's how it looks:

class Product < ActiveRecord::Base
  serialize :features, Array
  
  validates_presence_of :name
  validates_numericality_of :price
end

class ProductPresenter
  attr_reader :product
  
  def initialize(product)
    @product = product
  end
  
  # need this for formatting
  def helpers
    ActionController::Base.helpers
  end
  
  # for mass assignment
  def attributes=(hash)
    hash.each_pair do |key, val|
      self.send("#{key}=".to_sym, val)
    end
  end
  
  def price=(p)
    # expecting p to be something like "$4,000.00", set price to 4000.00
    p.gsub!(/[^0-9.]/, '')
    @product.price = p.to_f
  end
  
  def price
    helpers.number_to_currency(@product.price)
  end
  
  def features=(str)
    # expecting string with features separated by newlines
    @product.features = str.split("\n").collect {|f| f.strip }
  end
  
  def features
    @product.features.join("\n")
  end
  
  # proxy all other methods to @product
  def method_missing(method_name, *args, &block)
    @product.send(method_name, *args, &block)
  end
end

class ProductsController < ApplicationController
  def new
    @product = ProductPresenter.new(Product.new)
  end
  
  def edit
    product = Product.find(params[:id])
    @product = ProductPresenter.new(product)
  end
  
  def create
    @product = ProductPresenter.new(Product.new)
    @product.attributes = params[:product]
    if @product.save
      # success
    else
      render :action => 'new'
    end
  end
  
  def update
    p = Product.find(params[:id])
    @product = ProductPresenter.new(p)
    @product.attributes = params[:product]
    if @product.save
      # success
    else
      render :action => 'new'
    end
  end
end

<%# the product form %>
<% form_for :product, url => products_path do |f| %>
  <p class="form_item text_field">
    <label for="product[name]">Name:</label>
    <%= f.text_field :name %>
  </p>
  <p class="form_item text_field">
    <label for="product[price]">Price:</label>
    <%= f.text_field :price %>
  </p>
  <p class="form_item text_field">
    <label for="product[features]">Features (1 per line):</label>
    <%= f.text_area :features %>
  </p>
  <p class="form_item submit_button">
    <%= f.submit "Create Product" %>
  </p>
<% end %>

Our business and view logic have been effectively separated, our form code is clearer and the controller is only slightly more complicated. Because the ProductPresenter is acting as a proxy object to its Product object, we can simply treat it like a product thanks to 'duck typing'. While this example is a little contrived, using presenter classes can make or break your code base as you create complex model objects with equally complex visual representations.