10

I have a Rails project that, every now and then, throws this exception in production, in a non-reproducible manner. Everything works well in development and test, and apparently in production too, but ExceptionNotifier every few weeks emails me with this exception...

I have no idea what is going on, so I'm going to dump as much information about my environment as I think is relevant, in the hopes that some of this will help troubleshoot it.

  • Ruby 2.1.5
  • Rails 4.2.1
  • Running in Heroku, with regular Ruby Interpreter (ie. not JRuby)

The full error is:

"Circular dependency detected while autoloading constant DeferredUpdatesHelper"

DeferredUpdatesHelper is a module defined in lib/deferred_updates_helper.rb, as such:

module DeferredUpdatesHelper
  def self.something_something(params)
  end
end

I can't think of any dependencies this module has. It's very simple, and as far as I can tell, all it needs is a global variable called $RedisPool, so not sure how there can be a circular dependency...

This module is used from one of my models: models/user.rb

class User < ActiveRecord::Base
  def self.process_deferred_something
    DeferredUpdatesHelper.something_something(params) do
      # do stuff
    end
  end
end

That method is called from an ActiveJob:

class SomeJob < ActiveJob::Base
  queue_as :default

  def perform
    User.process_deferred_something
  end
end

Which is executed inside a Sidekiq process, and it runs perfectly happily every 10 minutes, except that every now and then I get one of these...

There are no require statement anywhere, or at least in any of these mentioned files... And as mentioned, in dev everything just works.

Stack Trace:

/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/dependencies.rb:492:in `load_missing_constant'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/dependencies.rb:184:in `const_missing'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/dependencies.rb:526:in `load_missing_constant'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/dependencies.rb:184:in `const_missing'
/app/app/models/user.rb:93:in `process_deferred_something'
/app/app/jobs/some_job.rb:5:in `perform'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/execution.rb:32:in `block in perform_now'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:117:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:117:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:343:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:343:in `block (2 levels) in simple'
/app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/active_job.rb:46:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/active_job.rb:46:in `perform'
/app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/active_job.rb:20:in `block (3 levels) in <top (required)>'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:441:in `instance_exec'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:441:in `block in make_lambda'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:342:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:342:in `block in simple'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:497:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:497:in `block in around'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:343:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:343:in `block (2 levels) in simple'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/logging.rb:23:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/logging.rb:23:in `block (4 levels) in <module:Logging>'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/notifications.rb:164:in `block in instrument'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/notifications.rb:164:in `instrument'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/logging.rb:22:in `block (3 levels) in <module:Logging>'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/logging.rb:43:in `block in tag_logger'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:68:in `block in tagged'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:26:in `tagged'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/tagged_logging.rb:68:in `tagged'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/logging.rb:43:in `tag_logger'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/logging.rb:19:in `block (2 levels) in <module:Logging>'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:441:in `instance_exec'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:441:in `block in make_lambda'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:342:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:342:in `block in simple'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:497:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:497:in `block in around'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:505:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:92:in `_run_callbacks'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:776:in `_run_perform_callbacks'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/execution.rb:31:in `perform_now'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/execution.rb:21:in `execute'
/app/vendor/bundle/ruby/2.1.0/gems/activejob-4.2.1/lib/active_job/queue_adapters/sidekiq_adapter.rb:40:in `perform'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:75:in `execute_job'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:52:in `block (2 levels) in process'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/app/lib/sidekiq_monitoring.rb:46:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/sidekiq.rb:33:in `block in call'
/app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:353:in `perform_action_with_newrelic_trace'
/app/vendor/bundle/ruby/2.1.0/gems/newrelic_rpm-3.11.2.286/lib/new_relic/agent/instrumentation/sidekiq.rb:29:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/logging.rb:24:in `with_context'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:132:in `call'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:51:in `block in process'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:98:in `stats'
/app/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:50:in `process'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `public_send'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `dispatch'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
/app/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'

Any idea what could be going on, or how I can fix it?

Daniel Magliola
  • 30,898
  • 61
  • 164
  • 243
  • Did you ever found out how to fix this? – Pwnna Aug 18 '15 at 16:54
  • Nope, still happens, in production, every now and then... – Daniel Magliola Aug 19 '15 at 17:51
  • 1
    I have this issue as well. I've correlated the errors to sometimes when the process restarts (it only happens during that, but not necessarily all the time). Is this true for you as well? I see you're using Rails42, can you check if https://github.com/rails/rails/commit/ae07806858072cd66611c165d1eed2a113e639e5 is applied to your branch? I can't upgrade to 42 just yet so I don't have this patch. – Pwnna Aug 20 '15 at 14:21
  • 1
    It's definitely on restarts. I'm on 4.2.3. Not sure if I have that patch – Daniel Magliola Aug 21 '15 at 18:27
  • 1
    Just checked, it looks like you have that patch at least on the `v4.2.3` tag. I'll look at it more when I get some more time. – Pwnna Aug 24 '15 at 14:27
  • Thanks! (now adding unnecessary chars just to comply with the minimum length) – Daniel Magliola Aug 25 '15 at 18:26
  • Patch `v4.2.3` does not help.. Same issues - circular dependency errors in sidekiq on heroku restart – mikdiet Nov 13 '15 at 13:14

1 Answers1

4

The circular dependency error sounds possibly like a multi-threading issue to me.

You could try adding lib to eager_load_paths like so:

config.eager_load_paths += ["#{config.root}/lib"]

While apps in production environments are eager loaded by default with config.eager_load!, lib is not an included path by. You can check what is included your eager_load_paths by running Rails.configuration.eager_load_paths in the console.

Not sure if this solves your issue but it's the only thing that came to my mind. Also if you have managed to solve your issue by now I'd love to hear an update on the solution.

uechan
  • 167
  • 8