by Dorian Karter on July 28, 2016

Rails provides before and after actions in controllers as an easy way to call methods before or after executing controller actions as response to route requests. Action Callbacks can be particularly helpful when implementing authentication/authorization for example, and are heavily used by gems such as Devise.

Unfortunately this feature can be awfully painful to debug. With many callbacks affecting your controllers this can be a rather arduous process to track down a nasty bug.

In this post I will focus on before_action for the sake of convenience, but the same technique can be applied to debug after_action and around_action.

Start by creating an anonymous before_action and inserting a pry statement into it.

class SomeController < ApplicationController
  before_action :authenticate_user!
end

Turns into:

class SomeController < ApplicationController
  before_action do
    require 'pry'; binding.pry
    authenticate_user!
  end
end

This is a good starting point for getting you exploring variables in the pry debugger. In fact, if you had defined authenticate_user! yourself you can just drop a binding.pry or puts directly in there without messing with the before actions.

But reality is far from ideal, and with all the layers of abstraction in Rails, various gems, inheritance and mixins, we often have to deal with a list of before actions happening without our control or knowledge. We are forced unwillingly to deep-dive into heavily abstracted, meta-programmed gems to debug a problem.

We often encounter this type of situation in apps we get from clients that use Devise. This is usually the fault of developers getting creative by overriding or worse so, monkey-patching a piece of Devise which causes a bug that is tightly related to Devise's code.

If you are dealing with such a problem (callbacks are not home brewed) and not sure where to start try using prepend_before_action and putting it at the bottom of your controller. This will ensure this callback will run first.

prepend_before_action do
  require 'pry'; binding.pry
  true
end

So we hit the controller action using the request to the route pointing at it and now we are in a pry session. The first thing you need to know about action callbacks is that they are stored behind the scenes in in a data structure called _process_action_callbacks. If you just write _process_action_callbacks in pry you will get a whole lot of information about all the action callbacks registered for the current request context:

[1] pry(#<SalesDashboardController>)> _process_action_callbacks
=> [#<ActiveSupport::Callbacks::Callback:0x007f95671589a8
  @callback_id=36,
  @chain=
   [#<ActiveSupport::Callbacks::Callback:0x007f95671589a8 ...>,
    #<ActiveSupport::Callbacks::Callback:0x007f9567153160
     @callback_id=34,
     @chain=[...],
     @compiled_options=[],
     @filter=:prepare_session,
     @kind=:before,
     @klass=ApplicationController,
     @options={:prepend=>true, :if=>[], :unless=>[]},
     @per_key={:if=>[], :unless=>[]},
     @raw_filter=:pr![](https://i.imgur.com/3hpeXMz.jpg)
epare_session>,
    #<ActiveSupport::Callbacks::Callback:0x007f956db44240
     @callback_id=32,
     @chain=[...],
     @compiled_options=[],
     @filter=:clear_search_path,
     @kind=:before,
     @klass=ApplicationController,
     @options={:prepend=>true, :if=>[], :unless=>[]},
     @per_key={:if=>[], :unless=>[]},
     @raw_filter=:clear_search_path>,
    #<ActiveSupport::Callbacks::Callback:0x007f956de429d8
     @callback_id=30,
     @chain=[...],
     @compiled_options=[],
     @filter=:authenticate_user!,
     @kind=:before,
     @klass=ApplicationController,
     @options={:prepend=>true, :if=>[], :unless=>[]},
     @per_key={:if=>[], :unless=>[]},
     @raw_filter=:authenticate_user!>,
    #<ActiveSupport::Callbacks::Callback:0x007f9564ef6428
     @callback_id=28,
     @chain=[...],
     @compiled_options=[],
     @filter=:set_search_path,
     @kind=:before,
     @klass=ApplicationController,
     @options={:prepend=>true, :if=>[], :unless=>[]},
     @per_key={:if=>[], :unless=>[]},
     @raw_filter=:set_search_path>,
# ....

That's a lot of information that we can use some ruby functions to filter (no pun intended) to just what we need. For example if we want to see the names of all the :before filters we can use the following query:

_process_action_callbacks.map { |c| c.filter if c.kind == :before }

Which yields something like this:

[13] pry(#<SalesDashboardController>)> _process_action_callbacks.map {|c| c.filter if c.kind == :before }
=> ["_callback_before_35",
 :prepare_session,
 :clear_search_path,
 :authenticate_user!,
 :set_search_path,
 :set_session_settings,
 :verify_authenticity_token,
 :handle_password_change,
 :set_paper_trail_whodunnit,
 :set_paper_trail_controller_info,
 :set_paper_trail_enabled_for_controller,
 "_callback_before_37",
 "_callback_before_39",
 "_callback_before_41",
 nil]

This command makes the callback hash more manageable and understandable, however it hides important details. If there are conditions attached to the filter such as only, except, if or unless. Also don't forget about prepend which affects the order of execution. These details are stored in options. A small tweak can be added to our query to improve the results:

_process_action_callbacks.map {|c| {c.filter => c.options} if c.kind == :before }

Now we get something that looks like this:

[14] pry(#<SalesDashboardController>)> _process_action_callbacks.map {|c| {c.filter => c.options} if c.kind == :before }
=> [{"_callback_before_35"=>{:prepend=>true, :if=>[], :unless=>[]}},
 {:prepare_session=>{:prepend=>true, :if=>[], :unless=>[]}},
 {:clear_search_path=>{:prepend=>true, :if=>[], :unless=>[]}},
 {:authenticate_user!=>{:prepend=>true, :if=>[], :unless=>[]}},
 {:set_search_path=>{:prepend=>true, :if=>[], :unless=>[]}},
 {:set_session_settings=>{:prepend=>true, :if=>[], :unless=>[]}},
 {:verify_authenticity_token=>{:prepend=>true, :if=>[], :unless=>[]}},
 {:handle_password_change=>{:if=>[], :unless=>[]}},
 {:set_paper_trail_whodunnit=>{:if=>[], :unless=>[]}},
 {:set_paper_trail_controller_info=>{:if=>[], :unless=>[]}},
 {:set_paper_trail_enabled_for_controller=>{:if=>[], :unless=>[]}},
 {"_callback_before_37"=>{:if=>[], :unless=>[], :only=>[:destroy]}},
 {"_callback_before_39"=>{:if=>[], :unless=>[]}},
 {"_callback_before_41"=>{:if=>[], :unless=>[]}},
 nil]

This improved output tells us that anonymous callback _callback_before_37 will only execute on the :destroy action. Good to know it's not relevant.

As you may have noticed a lot of callbacks are coming in from gems which we have included in our project. Say one of them is causing a silent error with no stack trace printed anywhere, we could use :Btabedit in Vim which is available to us from the excellent vim-bundler Vim plugin by Tim Pope. If we go with that approach it may prove cumbersome and tedious to go through each gem.

We can easily inspect the source of potentially suspect callbacks by using the show-source method in pry.

[18] pry(#<SalesDashboardController>)> show-source authenticate_user!

From: /Users/dev/.rvm/gems/ruby-1.9.3-p448/gems/devise-1.5.3/lib/devise/controllers/helpers.rb @ line 46:
Owner: Devise::Controllers::Helpers
Visibility: public
Number of lines: 4

def authenticate_#{mapping}!(opts={})
  opts[:scope] = :#{mapping}
  warden.authenticate!(opts) if !devise_controller? || opts.delete(:force)
end

Similar to show-source, Pry also offers the edit command which can be used for opening the file where the method is defined in our default editor:

[18] pry(#<SalesDashboardController>)> edit authenticate_user!

In my case this opens up Vim and puts me right where the method is defined, even if it was defined using meta-programming with class_eval (granted FILE and LINE were used). e.g.:

 42       def self.define_helpers(mapping) #:nodoc:
 43         mapping = mapping.name
 44
 45         class_eval <<-METHODS, __FILE__, __LINE__ + 1
              # CURSOR WILL BE ON LINE BELOW
 46           def authenticate_#{mapping}!(opts={})
 47             opts[:scope] = :#{mapping}
 48             warden.authenticate!(opts) if !devise_controller? || opts.delete(:force)
 49           end
 50
 51           def #{mapping}_signed_in?
 52             !!current_#{mapping}
 53           end

This allows us to quickly edit and save the gem file and insert a binding.pry so that we can debug that specific method.

Another option we have is monkey-patching the callback name being called in memory:

[21] pry(#<SalesDashboardController>)> authenticate_user!
=> #<User id: 332, email: "dev@hashrocket.com", encrypted_password: "xxx", reset_password_token: nil, reset_password_sent_at: nil, sign_in_count: 185, current_sign_in_at: "2016-07-15 15:32:22", last_sign_in_at: "2016-07-13 21:12:26", current_sign_in_ip: "127.0.0.1", last_sign_in_ip: "127.0.0.1", created_at: "2015-10-01 19:39:13", updated_at: "2016-07-15 15:32:22", first_name: "Hashrocket", last_name: "Hashrocket", job_title: "", role: nil, location: "", group: nil, role_id: 9, company_code: "test", phone: "", password_changed_at: "2016-07-13 21:12:13", remember_token: nil, remember_created_at: nil, branch_id: nil, deactivated: false>
[22] pry(#<SalesDashboardController>)> def authenticate_user!
[22] pry(#<SalesDashboardController>)*   puts ":::::::::::::::::DEBUG => AUTHENTICATING USER"
[22] pry(#<SalesDashboardController>)*   super
[22] pry(#<SalesDashboardController>)* end
=> nil
[23] pry(#<SalesDashboardController>)> authenticate_user!
:::::::::::::::::DEBUG => AUTHENTICATING USER
=> #<User id: 332, email: "dev@hashrocket.com", encrypted_password: "xxx", reset_password_token: nil, reset_password_sent_at: nil, sign_in_count: 185, current_sign_in_at: "2016-07-15 15:32:22", last_sign_in_at: "2016-07-13 21:12:26", current_sign_in_ip: "127.0.0.1", last_sign_in_ip: "127.0.0.1", created_at: "2015-10-01 19:39:13", updated_at: "2016-07-15 15:32:22", first_name: "Hashrocket", last_name: "Hashrocket", job_title: "Rocketeer", role: nil, location: "", group: nil, role_id: 9, company_code: "test", phone: "", password_changed_at: "2016-07-13 21:12:13", remember_token: nil, remember_created_at: nil, branch_id: nil, deactivated: false>
[24] pry(#<SalesDashboardController>)>

You can also define those monkey-patched methods in your controller if you think you will have multiple debug cycles and insert prys in all of them.

If you would like to do that for all action callbacks you can use the list you got in a previous step with some meta-programming wizardry:

["_callback_before_35",
   :prepare_session,
   :clear_search_path,
   :authenticate_user!,
   :set_search_path,
   :set_session_settings,
   :verify_authenticity_token,
   :handle_password_change,
   :set_paper_trail_whodunnit,
   :set_paper_trail_controller_info,
   :set_paper_trail_enabled_for_controller,
   "_callback_before_37",
   "_callback_before_39",
   "_callback_before_41",
  ].each do |cb|
    define_method(cb) { require 'pry'; binding.pry; super }
  end

Finally, if you want to automate the process you can combine some pieces from the code above into this:

_process_action_callbacks.each do |callback| 
  define_method(callback.filter) do
    puts "Running before_action: #{c.filter}"
    require 'pry'; binding.pry; 
    super 
  end if callback.kind == :before
end

Now you can use something like pry-byebug to step through your code and figure out the issue.

I hope this post was helpful in solving your action callback bugs and added some new tricks to your arsenal.