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.

