uninitialized constant ActiveRecord::Type from Rails.cache.fetch

jamo commented 8 years ago

Hey, I'm not fully sure if the exception I keep on getting is related to this gem; it started appearing recently, when I updated gems and migrated from dalli to redis cache and started using readthis.

And it appears for a kinda bad scenario, where there are four request coming for the cache with different id's at the same time... More below.

The setup:

Readthis (1.2.0)
Rails and it's parts (4.1.14.2)
Ubuntu 14.04.4 LTS
Phusion Passenger 5.0.26 (apache)
Rubygems: 2.6.2
Ruby: 2.2.1 (2015-02-26 patchlevel 85) [x86_64-linux]
Redis server v=3.0.7 sha=00000000:0 malloc=jemalloc-3.6.0 bits=64 build=95910942602714d9

Relevant config: code here

  config.cache_store = :readthis_store, {
        expires_in: 1.weeks.to_i, #default
        namespace: 'cache',
        redis: { url: ENV.fetch('REDIS_URL'), driver: :hiredis }
    }
    Readthis.fault_tolerant = true

So it exception comes from the line below: Full code here

@summary = Rails.cache.fetch("points_#{@course.id}_admin_#{current_user.administrator?}/", expires_in: 1.minutes) do

So, I've got four items wget -qO- https://example.com/courses/:id/points &> /dev/null in cron running every minute to keep the cache warm. Hacky, right :D. Anyways, all of these errors are for the last url in the cronjobs. So that's basically what leads me to believe that it could be either badly configured redis or maybe this gem / rails cache related issue. During last 24 hours, it seems, that I have gotten this exception seven times.

…pport-4.1.14.2/lib/active_support/inflector/
methods.rb: 240:in `const_get'
…pport-4.1.14.2/lib/active_support/inflector/
methods.rb: 240:in `block in constantize'
…pport-4.1.14.2/lib/active_support/inflector/
methods.rb: 236:in `each'
…pport-4.1.14.2/lib/active_support/inflector/
methods.rb: 236:in `inject'
…pport-4.1.14.2/lib/active_support/inflector/
methods.rb: 236:in `constantize'
…14.2/lib/active_support/core_ext/string/
inflections.rb:  66:in `constantize'
…upport-4.1.14.2/lib/active_support/core_ext/
marshal.rb:  10:in `rescue in load_with_autoloading'
…upport-4.1.14.2/lib/active_support/core_ext/
marshal.rb:   6:in `load_with_autoloading'
…/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
entity.rb:  67:in `load'
…s/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
cache.rb:  66:in `block in read'
….2.1/gems/connection_pool-2.2.0/lib/
connection_pool.rb:  64:in `block (2 levels) in with'
….2.1/gems/connection_pool-2.2.0/lib/
connection_pool.rb:  63:in `handle_interrupt'
….2.1/gems/connection_pool-2.2.0/lib/
connection_pool.rb:  63:in `block in with'
….2.1/gems/connection_pool-2.2.0/lib/
connection_pool.rb:  60:in `handle_interrupt'
….2.1/gems/connection_pool-2.2.0/lib/
connection_pool.rb:  60:in `with'
…s/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
cache.rb: 346:in `block in invoke'
…s/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
cache.rb: 338:in `block in instrument'
…vesupport-4.1.14.2/lib/active_support/
notifications.rb: 161:in `instrument'
…s/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
cache.rb: 338:in `instrument'
…s/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
cache.rb: 345:in `invoke'
…s/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
cache.rb:  63:in `read'
…s/ruby-2.2.1/gems/readthis-1.2.0/lib/readthis/
cache.rb: 142:in `fetch'
/home/tmc/srv/mooc/app/controllers/
points_controller.rb:  21:in `index'
….1.14.2/lib/action_controller/metal/
implicit_render.rb:   4:in `send_action'
…ms/actionpack-4.1.14.2/lib/abstract_controller/
base.rb: 189:in `process_action'
…pack-4.1.14.2/lib/action_controller/metal/
rendering.rb:  10:in `process_action'
…tionpack-4.1.14.2/lib/abstract_controller/
callbacks.rb:  20:in `block in process_action'
…activesupport-4.1.14.2/lib/active_support/
callbacks.rb: 113:in `call'
…activesupport-4.1.14.2/lib/active_support/
callbacks.rb: 113:in `call'
…activesupport-4.1.14.2/lib/active_support/
callbacks.rb: 552:in `block (2 levels) in compile'
…activesupport-4.1.14.2/lib/active_support/
callbacks.rb: 502:in `call'
…activesupport-4.1.14.2/lib/active_support/
callbacks.rb: 502:in `call'
…activesupport-4.1.14.2/lib/active_support/
callbacks.rb:  86:in `run_callbacks'
…tionpack-4.1.14.2/lib/abstract_controller/
callbacks.rb:  19:in `process_action'
…ionpack-4.1.14.2/lib/action_controller/metal/
rescue.rb:  29:in `process_action'
…r/rails_ext/action_controller/metal/
instrumentation.rb:  34:in `block in process_action'
…vesupport-4.1.14.2/lib/active_support/
notifications.rb: 159:in `block in instrument'
….14.2/lib/active_support/notifications/
instrumenter.rb:  20:in `instrument'
…vesupport-4.1.14.2/lib/active_support/
notifications.rb: 159:in `instrument'
…r/rails_ext/action_controller/metal/
instrumentation.rb:  21:in `process_action'
…4.1.14.2/lib/action_controller/metal/
params_wrapper.rb: 250:in `process_action'
….14.2/lib/active_record/railties/
controller_runtime.rb:  18:in `process_action'
…ms/actionpack-4.1.14.2/lib/abstract_controller/
base.rb: 136:in `process'
…/gems/actionview-4.1.14.2/lib/action_view/
rendering.rb:  30:in `process'
…ems/actionpack-4.1.14.2/lib/action_controller/
metal.rb: 196:in `dispatch'
….1.14.2/lib/action_controller/metal/
rack_delegation.rb:  13:in `dispatch'
…ems/actionpack-4.1.14.2/lib/action_controller/
metal.rb: 232:in `block in action'
…pack-4.1.14.2/lib/action_dispatch/routing/
route_set.rb:  80:in `call'
…pack-4.1.14.2/lib/action_dispatch/routing/
route_set.rb:  80:in `dispatch'
…pack-4.1.14.2/lib/action_dispatch/routing/
route_set.rb:  48:in `call'
…ionpack-4.1.14.2/lib/action_dispatch/journey/
router.rb:  73:in `block in call'
…ionpack-4.1.14.2/lib/action_dispatch/journey/
router.rb:  59:in `each'
…ionpack-4.1.14.2/lib/action_dispatch/journey/
router.rb:  59:in `call'
…pack-4.1.14.2/lib/action_dispatch/routing/
route_set.rb: 690:in `call'
…/gems/ruby-2.2.1/gems/rack-cors-0.4.0/lib/rack/
cors.rb:  80:in `call'
…l/rvm/gems/ruby-2.2.1/gems/rack-1.5.5/lib/rack/
etag.rb:  23:in `call'
…/ruby-2.2.1/gems/rack-1.5.5/lib/rack/
conditionalget.rb:  25:in `call'
…l/rvm/gems/ruby-2.2.1/gems/rack-1.5.5/lib/rack/
head.rb:  11:in `call'
…1.14.2/lib/action_dispatch/middleware/
params_parser.rb:  27:in `call'
…npack-4.1.14.2/lib/action_dispatch/middleware/
flash.rb: 254:in `call'
…-2.2.1/gems/rack-1.5.5/lib/rack/session/abstract/
id.rb: 225:in `context'
…-2.2.1/gems/rack-1.5.5/lib/rack/session/abstract/
id.rb: 220:in `call'
…ack-4.1.14.2/lib/action_dispatch/middleware/
cookies.rb: 562:in `call'
…activerecord-4.1.14.2/lib/active_record/
query_cache.rb:  36:in `call'
…record/connection_adapters/abstract/
connection_pool.rb: 621:in `call'
…k-4.1.14.2/lib/action_dispatch/middleware/
callbacks.rb:  29:in `block in call'
…activesupport-4.1.14.2/lib/active_support/
callbacks.rb:  82:in `run_callbacks'
…k-4.1.14.2/lib/action_dispatch/middleware/
callbacks.rb:  27:in `call'
…k-4.1.14.2/lib/action_dispatch/middleware/
remote_ip.rb:  76:in `call'
…4.2/lib/action_dispatch/middleware/
debug_exceptions.rb:  17:in `call'
…14.2/lib/action_dispatch/middleware/
show_exceptions.rb:  30:in `call'
…-2.2.1/gems/railties-4.1.14.2/lib/rails/rack/
logger.rb:  38:in `call_app'
…-2.2.1/gems/railties-4.1.14.2/lib/rails/rack/
logger.rb:  20:in `block in call'
…esupport-4.1.14.2/lib/active_support/
tagged_logging.rb:  68:in `block in tagged'
…esupport-4.1.14.2/lib/active_support/
tagged_logging.rb:  26:in `tagged'
…esupport-4.1.14.2/lib/active_support/
tagged_logging.rb:  68:in `tagged'
…-2.2.1/gems/railties-4.1.14.2/lib/rails/rack/
logger.rb:  20:in `call'
…ms/request_store-1.3.0/lib/request_store/
middleware.rb:   9:in `call'
…-4.1.14.2/lib/action_dispatch/middleware/
request_id.rb:  21:in `call'
…/ruby-2.2.1/gems/rack-1.5.5/lib/rack/
methodoverride.rb:  21:in `call'
…vm/gems/ruby-2.2.1/gems/rack-1.5.5/lib/rack/
runtime.rb:  17:in `call'
…m/gems/ruby-2.2.1/gems/rack-1.5.5/lib/rack/
sendfile.rb: 112:in `call'
…/ruby-2.2.1/gems/railties-4.1.14.2/lib/rails/
engine.rb: 514:in `call'
…-2.2.1/gems/railties-4.1.14.2/lib/rails/
application.rb: 144:in `call'
…ruby-2.2.1/gems/railties-4.1.14.2/lib/rails/
railtie.rb: 194:in `public_send'
…ruby-2.2.1/gems/railties-4.1.14.2/lib/rails/
railtie.rb: 194:in `method_missing'
…lib/phusion_passenger/rack/
thread_handler_extension.rb:  97:in `process_request'
…ib/phusion_passenger/request_handler/
thread_handler.rb: 152:in `accept_and_process_next_request'
…ib/phusion_passenger/request_handler/
thread_handler.rb: 113:in `main_loop'
…c/ruby_supportlib/phusion_passenger/
request_handler.rb: 416:in `block (3 levels) in start_threads'
…-5.0.26/src/ruby_supportlib/phusion_passenger/
utils.rb: 113:in `block in create_thread_and_abort_on_exception'

sorentwo commented 8 years ago

It seems like the error is coming from marshaling whatever is being cached. In a multi threaded setup the auto load behavior can cause a race condition where a class isn't loaded yet.

What is the value being cached? Can you use an explicit require? Alternately, can it be represented as JSON, in which case you can try using JSON serialization instead for that particular cache request.

jamo commented 8 years ago

Due to our need of Dir.chdir {}, we are using the running multiprocess but singlethreaded passenger.

The content is basically this: https://tmc.mooc.fi/mooc/courses/35/points - a aggregated point list - which is mosty just hash of numbers with User AR objects. The converting it fully to json might actually be a nice optimization.

Basically all of the objects are models, so I would have expected for those to be required. But I'll try to require those explicitly.

Also, now that I changed the cron not to run the request in parallel I'm no longer seeing these exceptions.

Thanks, I'll manage, I just wanted to check if I ran into a race condition in this gem :)

sorentwo commented 8 years ago

Again, thanks for the report. If there is anything I can fix please leave an update.

sorentwo / readthis

uninitialized constant ActiveRecord::Type from Rails.cache.fetch #40