Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Don't treat NameError in deserialize as network error #728

Merged
merged 2 commits into from Jul 26, 2019
Merged

Don't treat NameError in deserialize as network error #728

merged 2 commits into from Jul 26, 2019

Conversation

@michaelkl
Copy link
Contributor

@michaelkl michaelkl commented Jul 25, 2019

General

The problem I have stumbled upon after upgrading Rails version of my Ruby on Rails application was dalli marking a memcached server as failed and removing it from the list of servers for 60 seconds. In application log it looked like this:

Cache write: operator_name_cache/0/2 ({:expires_in=>2 days})
down_retry_delay not reached for memcached:11211 (59.990 seconds left)
DalliError: No server available
Cache write: operator_name_cache/0/17 ({:expires_in=>2 days})
down_retry_delay not reached for memcached:11211 (59.989 seconds left)
DalliError: No server available
Cache read: api_v1_results_hotel_data/453718 ({:expires_in=>3 hours})
down_retry_delay not reached for memcached:11211 (59.989 seconds left)

After a lot of debugging I discovered the following error in my production log:

#<Dalli::NetworkError: memcached:11211 is down: NameError uninitialized constant ActiveRecord::PredicateBuilder::ClassHandler
Did you mean?  ActiveRecord::PredicateBuilder::BaseHandler>
retrying request with new server
down_retry_delay not reached for memcached:11211 (60.000 seconds left)

This means dalli has run into NameError while deserializing object, and treated this error as memcached server error!

Reproducing the error

I've made a simple code snippet to reproduce the error.
First, let's define a simple test class:

require 'dalli'
require 'active_support'
require 'active_support/core_ext'

module M
    class C
      def initialize(v)
        @v = v
      end

      def to_s
        @v.to_s
      end
    end
end

Next, instantiate and object and save it to memcache:

[5] pry(main)> o = M::C.new('test')
=> #<M::C:0x00005591884f3b38 @v="test">
[6] pry(main)> dalli = Dalli::Client.new
=> #<Dalli::Client:0x000055918852aed0 @options={}, @ring=nil, @servers=["127.0.0.1:11211"]>
[7] pry(main)> dalli.set :my_object, o
=> 12397565349220843520
[8] pry(main)> dalli.get :my_object
=> #<M::C:0x00005591885b28f8 @v="test">

Things look good so far. But let's do the trick: remove M::C class and try again.

[9] pry(main)> M.instance_eval { remove_const :C }
=> M::C
[10] pry(main)> dalli.get :my_object
E, [2019-07-25T09:44:26.341917 #27755] ERROR -- : Unexpected exception during Dalli request: NameError: uninitialized constant M::C
E, [2019-07-25T09:44:26.342009 #27755] ERROR -- : /home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/inflector/methods.rb:285:in `const_get'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/inflector/methods.rb:285:in `block in constantize'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/inflector/methods.rb:281:in `each'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/inflector/methods.rb:281:in `inject'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/inflector/methods.rb:281:in `constantize'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/core_ext/string/inflections.rb:68:in `constantize'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/core_ext/marshal.rb:10:in `rescue in load'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/core_ext/marshal.rb:5:in `load'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/server.rb:442:in `deserialize'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/server.rb:513:in `generic_response'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/server.rb:272:in `get'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/server.rb:70:in `request'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/options.rb:19:in `block in request'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/options.rb:18:in `request'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/client.rb:368:in `perform'
	/home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/client.rb:59:in `get'
	(pry):20:in `__pry__'
	...
W, [2019-07-25T09:44:26.342183 #27755]  WARN -- : 127.0.0.1:11211 is down
Dalli::RingError: No server available

We got it! Unexpected exception NameError led us to WARN -- : 127.0.0.1:11211 is down. And the one to blame is ActiveSupport's internal call for const_get.

Redemption

The solution to this problem is simple: we should handle this kind on NameError as it's already done to ArgumentError in Dalli::Server#deserialize.

After applying the proposed patch running the same test snippet ends up like this:

[10] pry(main)> dalli.get :my_object
Dalli::UnmarshalError: Unable to unmarshal value: uninitialized constant M::C
from /home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/dalli-2.7.10/lib/dalli/server.rb:452:in `rescue in deserialize'
Caused by NameError: uninitialized constant M::C
from /home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/inflector/methods.rb:285:in `const_get'
Caused by ArgumentError: undefined class/module M::C
from /home/mike/.rbenv/versions/2.5.3/lib/ruby/gems/2.5.0/gems/activesupport-5.2.3/lib/active_support/core_ext/marshal.rb:6:in `load'
@prikha
Copy link

@prikha prikha commented Jul 25, 2019

Nice catch actually! 👍

@siddharth1001
Copy link

@siddharth1001 siddharth1001 commented Jul 25, 2019

👍 @michaelkl
I had faced the same issue while migrating from Rails 3 to Rails 4 and fixed this with monkey-patching Dalli-2.7.9. This will be very useful for other folks while upgrading Rails.

@mperham
Copy link
Collaborator

@mperham mperham commented Jul 26, 2019

Nice work. Possible to add a simple test?

@michaelkl
Copy link
Contributor Author

@michaelkl michaelkl commented Jul 26, 2019

@mperham Done!

@petergoldstein
Copy link
Owner

@petergoldstein petergoldstein commented Jul 26, 2019

@michaelkl This is great. Thanks for the contribution. Merging.

@petergoldstein petergoldstein merged commit 8b19276 into petergoldstein:master Jul 26, 2019
1 check passed
@michaelkl michaelkl deleted the deserialize-name-error branch Jul 26, 2019
@ilove8
Copy link

@ilove8 ilove8 commented Nov 5, 2019

@petergoldstein Hi, What about update this commit to next version 2.7.11. It will be very helpful :)

@hovissimo
Copy link

@hovissimo hovissimo commented Jan 22, 2020

@petergoldstein More attention on this issue, please. We got punked by this during an upgrade and are forced to vendor this gem to get the fix. Can we please get a fix release?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

7 participants