Introducing Whiny Validation. So You Can Figure Out Why Your Rails Specs Failed.

whining_boySometimes when I write a spec in a Rails app, it fails silently but it isn’t clear why. For example, here’s a pretty standard (if minimal) controller spec:

  describe "POST 'create'" do
    it "makes a new customer" do
      post :create
      expect(response).to redirect_to Customer.last
    end
  end

Or perhaps you would use expect { post :create } to change { Customer.count }.by(1). Either way, I run this spec, and the error message doesn’t give me enough information about why it failed:

$ rspec spec/controllers/customers_controller_spec.rb
F

Failures:

  1) CustomersController POST 'create' makes a new customer
     Failure/Error: expect(response).to redirect_to Customer.last
       Expected response to be a <:redirect>, but was <200>
     # /Users/brian/.rvm/gems/ruby-1.9.3-p385/gems/rspec-expectations-2.13.0/lib/rspec/expectations/fail_with.rb:32:in `fail_with'
     # /Users/brian/.rvm/gems/ruby-1.9.3-p385/gems/rspec-expectations-2.13.0/lib/rspec/expectations/handler.rb:33:in `handle_matcher'
     # /Users/brian/.rvm/gems/ruby-1.9.3-p385/gems/rspec-expectations-2.13.0/lib/rspec/expectations/expectation_target.rb:34:in `to'
     # ./spec/controllers/customers_controller_spec.rb:8:in `block (3 levels) in <top (required)>'
...

How would you debug this to figure out what you did wrong? One thing you could do: look at the log. But it doesn’t help much:

Processing by CustomersController#create as HTML
   (0.1ms)  SAVEPOINT active_record_1
   (0.1ms)  ROLLBACK TO SAVEPOINT active_record_1
  Rendered customers/new.html.haml within layouts/application (0.2ms)
Completed 200 OK in 55ms (Views: 41.0ms | ActiveRecord: 1.7ms)
  Customer Load (0.6ms)  SELECT "customers".* FROM "customers" ORDER BY "customers"."id" DESC LIMIT 1
   (0.1ms)  ROLLBACK

Hmm, no clues there. At this point, if a code inspection doesn’t help, I would typically resort to inserting a debugger statement or various puts statements. It’s not a very efficient way to work.

But I’ve noticed that frequently, this type of spec failure is due to an input validation error. That’s why I created the Whiny Validation gem.

Whiny Validation watches for ActiveRecord validation errors on all models. Whenever one occurs, it logs the validation message and dumps the ActiveRecord object (with inspect) to the log. All you have to do is search the log for the word “validation,” or browse through the log and the yellow text should jump out at you.

To make it work, simply add this to your Gemfile:

gem 'whiny_validation'

Now rerun the spec and look at the log:

Processing by CustomersController#create as HTML
   (0.1ms)  SAVEPOINT active_record_1
  Validation failed  #<Customer id: nil, email: nil, created_at: nil, updated_at: nil>
    => Email can't be blank
   (0.1ms)  ROLLBACK TO SAVEPOINT active_record_1
  Rendered customers/new.html.haml within layouts/application (0.2ms)
Completed 200 OK in 28ms (Views: 11.7ms | ActiveRecord: 2.3ms)
  Customer Load (0.5ms)  SELECT "customers".* FROM "customers" ORDER BY "customers"."id" DESC LIMIT 1
   (0.1ms)  ROLLBACK

Let’s see that in full color:

Whiny Validation

That’s much better. It tells me that a validation failed, it shows the object that had the failure, and it shows the validation error message. Now it’s easy to see my mistake: I forgot to pass in an email address to the “create” action in my spec. When I change the spec to this, it passes:

post :create, customer: { email: "test@example.com" }

How Does it Work?

Here is the entire implementation, with the exception of the configuration code:

module WhinyValidation
  extend ActiveSupport::Concern

  included do
    after_validation :whiny_validation,
      :if => proc { |model| model.errors.present? }
  end

  def whiny_validation
    ActiveSupport::Notifications.instrument(
      "validation_failed.whiny_validation",
      :object => self,
      :error_messages => errors.full_messages)
  end

  class LogSubscriber < ActiveSupport::LogSubscriber
    def validation_failed(event)
      debug do
        name = color("Validation failed", YELLOW, true)
        object = event.payload[:object]
        error_messages = color(
          event.payload[:error_messages].map {|message|
            "    => #{message}"
          }.join("\n"), YELLOW
        )

        "  #{name}  #{object.inspect}\n#{error_messages}"
      end
    end
  end

  WhinyValidation::LogSubscriber.attach_to :whiny_validation
end

module ActiveRecord
  class Base
    include WhinyValidation
  end
end

Let’s break this down. First, let’s look at the beginning and the end of the file:

module WhinyValidation
  extend ActiveSupport::Concern

  included do
    after_validation :whiny_validation,
      :if => proc { |model| model.errors.present? }
  end
end

module ActiveRecord
  class Base 
    include WhinyValidation
  end
end

ActiveSupport::Concern lets me be notified when this module is included elsewhere, using the included statement. At the end of the file, I include WhinyValidation in ActiveRecord::Base. The included statement gets run, so it adds an after_validation callback to every subclass of ActiveRecord::Base. The callback calls my whiny_validation method if any errors were detected during validation.

Next, let’s take a look at the whiny_validation method itself:

  def whiny_validation
    ActiveSupport::Notifications.instrument(
      "validation_failed.whiny_validation",
      :object => self,
      :error_messages => errors.full_messages)
  end

What I want to do is write to the logfile. I could just have written logger.debug, but I want to use color in my message and ActiveSupport::LogSubscriber has helper methods for writing to the log with color. So I call ActiveSupport::Notifications.instrument (which means “broadcast a notification”) and I pass two things:

  1. A string with two parts, separated by a dot: first the name of an event, followed by a namespace. (I’m not sure why the namespace comes last. It feels backward to me.)
  2. The payload, which is a hash. What belongs in the payload? It’s up to you when you define a notification. I decided I include the ActiveRecord object whose validation failed, and the full list of error messages.

Next, someone has to listen to the notification and do the logging. I created a class named LogSubscriber in the WhinyValidation namespace, and made it a subclass of ActiveSupport::LogSubscriber so I can use that color method:

  class LogSubscriber < ActiveSupport::LogSubscriber
    def validation_failed(event)
      debug do
        name = color("Validation failed", YELLOW, true)
        object = event.payload[:object]
        error_messages = color(
          event.payload[:error_messages].map {|message|
            "    => #{message}"
          }.join("\n"), YELLOW
        )

        "  #{name}  #{object.inspect}\n#{error_messages}"
      end
    end
  end

The first line of validation_failed is debug do. Since we’re in a subclass of ActiveSupport::LogSubscriber, methods are defined for all the logger levels. You don’t have to call Rails.logger.debug, just call debug. (Actually, the real implementation calls send(WhinyValidation.configuration.log_level), because the log level is configurable. I simplified it for this blog post.)

By the way, most people don’t realize that when you call the logger, you are allowed to pass in a block. Whatever the block returns gets converted to a string with .to_s and then is output to the log. I used that trick here so that in any environment that doesn’t have the log_level set to debug, the code doesn’t have to waste time constructing a message.

Next, I call ActiveSupport::LogSubscriber‘s helper method color and pass in the YELLOW constant (also defined in ActiveSupport::LogSubscriber), to colorize the “Validation failed” string. The true means “make it bold.”

Then I do the same thing with the error messages, making them yellow and concatenating them.

The last thing I do is return a string which includes the “Validation failed” message, an inspection of the object that was invalid, and the list of error messages.

Finally, we have to hook it up:

  WhinyValidation::LogSubscriber.attach_to :whiny_validation

The last line is calling a method whose implementation is in the base class, ActiveSupport::LogSubscriber. It tells my LogSubscriber class to watch for ActiveSupport notifications that use the “whiny_validation” namespace. Whenever one occurs, it extracts the event name (in this case, “validation_failed”) and looks for a method by that name. If it exists, it calls it and passes in an event object.

One of the methods on the event object is payload, which returns the hash that I passed in.

Conclusion

This turned out to be pretty easy because:

  1. Ruby lets you extend existing classes, so I was able to inject my own after_validation hook into ActiveRecord::Base.
  2. ActiveSupport::Notifications and ActiveSupport::LogSubscriber work together to make it really easy to log anything that broadcasts a notification, and to log with color.

Go ahead and use this in your projects. Please let me know if you liked it.

One last note: if you want to configure it to log at the :info level or any other level, take a look at the README. It tells you how.

4 thoughts on “Introducing Whiny Validation. So You Can Figure Out Why Your Rails Specs Failed.”

    1. No, I don’t see any reason to use this on production. I’m not sure what you would get out of it.

      But you can if you want to:

      # config/initializers/whiny_validation.rb
      WhinyValidation.configure do |config|
        config.log_level = :info
      end
      

Leave a Reply

Your email address will not be published. Required fields are marked *

Feel free to use <a>, <b>, <i>, <strong>, <em>, <strike>, <code>.

Code blocks:
[code language="ruby/javascript/html/css/sass/bash"]
[/code]