Rails.cache.read in sidekiq process

Question

In my Ruby on Rails application I have model that looks like this:

class Schema < ActiveRecord::Base
  has_many :schema_items

  def self.from_cache(schema_id)
    schema = Rails.cache.read("schema_#{schema_id}")
    unless schema
      schema = Schema.where(id: schema_id).includes(:schema_items).first
      Rails.cache.write("schema_#{schema_id}", schema) if schema
    end
    schema
  end
end

I'm using this class method in other class which is called by Sidekiq worker. From time to time it returns the following error:

NotImplementedError

Using google I found this issue in redis_store gem: https://github.com/redis-store/redis-store/issues/74

But they fix this bug. My app is hosted on Heroku and I'm using the RedisCloud. Any ideas how can I solve this?

EDIT:

Here is the full backtrace:

NotImplementedError: NotImplementedError
  from celluloid/tasks/task_fiber.rb:15:in `block in create'
  from celluloid/tasks.rb:57:in `block in initialize'
  from celluloid/actor.rb:357:in `block in task'
  from celluloid/cell.rb:71:in `block in task'
  from celluloid/cell.rb:60:in `block in invoke'
  from celluloid/calls.rb:122:in `dispatch'
  from celluloid/calls.rb:26:in `dispatch'
  from celluloid/calls.rb:26:in `public_send'
  from sidekiq/processor.rb:50:in `process'
  from sidekiq/processor.rb:98:in `stats'
  from sidekiq/processor.rb:51:in `block in process'
  from sidekiq/middleware/chain.rb:132:in `invoke'
  from sidekiq/middleware/chain.rb:132:in `call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from sidekiq/middleware/server/logging.rb:11:in `call'
  from sidekiq/logging.rb:30:in `with_context'
  from sidekiq/middleware/server/logging.rb:15:in `block in call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from sidekiq/failures/middleware.rb:9:in `call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from sidekiq/middleware/server/retry_jobs.rb:74:in `call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from sidekiq/middleware/server/active_record.rb:6:in `call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from sidekiq/batch/middleware.rb:25:in `call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from sidekiq_unique_jobs/middleware/server/unique_jobs.rb:16:in `call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from sidetiq/middleware/history.rb:8:in `call'
  from sidekiq/middleware/chain.rb:129:in `block in invoke'
  from new_relic/agent/instrumentation/sidekiq.rb:29:in `call'
  from new_relic/agent/instrumentation/controller_instrumentation.rb:352:in `perform_action_with_newrelic_trace'
  from new_relic/agent/instrumentation/sidekiq.rb:33:in `block in call'
  from sidekiq/middleware/chain.rb:127:in `block in invoke'
  from sidekiq/processor.rb:52:in `block (2 levels) in process'
  from sidekiq/processor.rb:75:in `execute_job'
  from app/workers/response_processor_worker.rb:8:in `perform'
  from app/services/import/response_processor.rb:28:in `process'
  from app/models/import/importer/raw_response_validator.rb:17:in `validate'
  from app/models/survey_schema.rb:51:in `from_cache'
  from active_record/relation/finder_methods.rb:127:in `first'
  from active_record/relation/finder_methods.rb:484:in `find_nth'
  from active_record/relation/finder_methods.rb:500:in `find_nth_with_limit'
  from active_record/relation.rb:243:in `to_a'
  from active_record/relation.rb:514:in `load'
  from active_record/relation.rb:643:in `exec_queries'
  from active_record/relation.rb:643:in `each'
  from active_record/relation.rb:644:in `block in exec_queries'
  from active_record/associations/preloader.rb:102:in `preload'
  from active_record/associations/preloader.rb:102:in `flat_map'
  from active_record/associations/preloader.rb:102:in `each'
  from active_record/associations/preloader.rb:103:in `block in preload'
  from active_record/associations/preloader.rb:115:in `preloaders_on'
  from active_record/associations/preloader.rb:143:in `preloaders_for_one'
  from active_record/associations/preloader.rb:143:in `flat_map'
  from active_record/associations/preloader.rb:143:in `each'
  from active_record/associations/preloader.rb:144:in `block in preloaders_for_one'
  from active_record/associations/preloader.rb:144:in `map'
  from active_record/associations/preloader.rb:144:in `each'
  from active_record/associations/preloader.rb:146:in `block (2 levels) in preloaders_for_one'
  from active_record/associations/preloader/association.rb:20:in `run'
  from active_record/associations/preloader/collection_association.rb:13:in `preload'
  from active_record/associations/preloader/association.rb:78:in `associated_records_by_owner'
  from active_record/associations/preloader/association.rb:60:in `owners_by_key'
  from active_record/associations/preloader/association.rb:103:in `key_conversion_required?'
  from active_record/associations/preloader/association.rb:107:in `association_key_type'
  from active_record/associations/preloader/association.rb:45:in `association_key_name'

and my worker looks like this:

class ResponseCreatorWorker
  include Sidekiq::Worker

  sidekiq_options queue: :response_processing

  def perform(schema_id)
    # some not important code
    schema = Schema.from_cache(schema_id) # this line throws the error
    Response.create(schema: schema)
  end
end

Answer 1

A couple options without being able to go into the Pro code:

Error you found is redis-store related, try memcached

Try moving the cache to memcached, it should be a simple and non-disruptive action, cost-free on simple plans, and see if the problem goes away, or changes, could be useful for hunting the core bug down

memcache is a better caching service anyway for simple key-value stuff,

The worker you linked is not a part of the stack trace

You showed the ResponseCreatorWorker, but that does not appear in the stack trace. What appears is ResponseProcessorWorker, maybe link that worker instead?

Are you sure you are running the code you are running?

Mike Perham says that the Sidekiq backtrace doesn't match the version you have given him, and the wrong worker is in the stack trace? Are you really sure the server is updating? Review the deployment log and log in to the worker with heroku run bash and inspect a couple of key files, make sure nothing is off with the platform.

Can you rescue it? :D

It should be pretty safe to put in a rescue that catches NotImplementedError, tries once again, and logs a record of it into the logs. Update gems when appropriate and when warnings disappear open a whiskey and celebrate.

Put something like this in your model:

def wrap_me_scotty
  yield
rescue NotImplementedError => e
  warn "#{e} :-("
  yield # try once more, let it explode if no joy
end

and then wrap Rails.cache calls

def self.from_cache(schema_id)
  schema = wrap_me_scotty{ Rails.cache.read("schema_#{schema_id}") }
  unless schema
    schema = Schema.where(id: schema_id).includes(:schema_items).first
    wrap_me_scotty{ Rails.cache.write("schema_#{schema_id}", schema) } if schema
  end
  schema
end