An Adventure in Debugging Gems and Ruby Mixins
Occasionally when upgrading gems, breaking changes come along and require debugging and fixing the issue. Oftentimes going through the README, CHANGELOG and other files within the gem’s repository can help solve and shed light on any issues. Sometimes, though, there is more at play.
Recently while upgrading Handshake’s rails version from 4.2.1 to 4.2.3 one such issue arised. We have an API used for data syncing and integrations, and this API is of course well tested. The tests use a common test helper to make API calls which ends up doing a simple get, put, delete or post with the passed params and an API token for authentication. After upgrading these cryptic errors started showing up:
Failure/Error: api_call "/api/v1/educations", 'post', education_params
Module::DelegationError:
ActionDispatch::Response#[] delegated to @header.[], but @header is nil: #<ActionDispatch::TestResponse:0x007f9740e66660 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007f9740e66610>, @stream=#<ActionDispatch::Response::Buffer:0x007f9740e66570 @response=#<ActionDispatch::TestResponse:0x007f9740e66660 ...>, @buf=["{\"success\":false}"], @closed=false>, @header=nil, @status=200, @sending_file=false, @blank=false, @cv=#<MonitorMixin::ConditionVariable:0x007f9740e66548 @monitor=#<ActionDispatch::TestResponse:0x007f9740e66660 ...>, @cond=#<Thread::ConditionVariable:0x007f9740e66520>>, @committed=false, @sending=false, @sent=false, @content_type=nil, @charset=nil>
# ./spec/support/request_helpers.rb:30:in `api_call'
# ./spec/requests/api/v1/educations_spec.rb:13:in `block (3 levels) in <top (required)>'
# -e:1:in `<main>'
And so the search began. Starting with the changelog, there were changes that appeared to be relevant to this area, indicating that there may be a change in rails that was causing this. However the changes are pretty large and nothing obvious stands out.
After some exploring of other gems and trying some other updates, I decided it might be worth to try debugging rails and see where that gets me. This was much easier than I expected due to the awesomeness that is bundler. Instead of having
gem ‘rails’, ‘~> 4.2.3’
in your Gemfil you 1) Fork rails 2) Clone locally 3) Add this to your gemfile instead:
gem ‘rails’, github: ‘sgringwe/rails’, branch: ‘master’
and then lastly run
bundle local gem.rails ~/code/rails
which will tell bundler to use your local copy rather than remote. Now you can edit and debug the source code in your local rails, awesome! Just remember to reload your rails app (which may require restarting spring) after every change since each gem is cached.
Debugging the Actual Issue
Now that we can edit the rails source as we wish, let’s try and figure out what’s going on. After some digging into the action dispatch response and response_test classes it’s clear that the headers are being passed into the response as expected but for some reason after the initializer are set to nil. Hmmm.
Eventually I get to the point in the code where nil is being set:
def merge_default_headers(original, default)
default.respond_to?(:merge) ? default.merge(original) : original
end
For this function ‘default’ is the default set of headers that rails uses to be secure by default. These can be overriden in your application’s config files. ‘original’ is the custom headers being used for the call, such as API tokens.
When this call is made, ‘original’ is set to a hash containing our API Token and default is set to nil. So surely it would simply be returning ‘original’, right? No! After printing some debug statements we find out that
- default is nil
- default.class is NilObject
- default.respond_to?(:merge) is true!
- default.is_a?(Hash) is false
Crazy! How is this happening? A handy method call to ‘default.method(:merge)’ tells us that CanCan::Ability has defined the merge method on NilObject somehow. Aren’t mixins beautiful?
After hours of debugging I removed my scattered lines of puts statements and a PR is now submitted and ready for review: https://github.com/rails/rails/pull/20840.