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

Already on GitHub? Sign in to your account

Random wrong number of arguments(1 for 0) #601

Closed
xdmx opened this Issue Dec 27, 2012 · 10 comments

Comments

4 participants

xdmx commented Dec 27, 2012

I'm using Sidekiq to delay various parts of my app, one of these are email delivery. Sometimes I get failed jobs, like the following (error tracked by exceptional):

# (ArgumentError) "wrong number of arguments(1 for 0)"

/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/association.rb:98:in `initialize'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/association.rb:98:in `new'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/association.rb:98:in `association_scope'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/association.rb:87:in `scoped'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/singular_association.rb:42:in `find_target'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/association.rb:145:in `load_target'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/association.rb:55:in `reload'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/singular_association.rb:9:in `reader'
/app/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.9/lib/active_record/associations/builder/association.rb:44:in `block in define_readers'
/app/app/mailers/notifier.rb:16:in `new_message'
/app/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/base.rb:167:in `process_action'
/app/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/base.rb:121:in `process'
/app/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/rendering.rb:45:in `process'
/app/vendor/bundle/ruby/1.9.1/gems/actionmailer-3.2.9/lib/action_mailer/base.rb:458:in `process'
/app/vendor/bundle/ruby/1.9.1/gems/actionmailer-3.2.9/lib/action_mailer/base.rb:452:in `initialize'
/app/vendor/bundle/ruby/1.9.1/gems/actionmailer-3.2.9/lib/action_mailer/base.rb:439:in `new'
/app/vendor/bundle/ruby/1.9.1/gems/actionmailer-3.2.9/lib/action_mailer/base.rb:439:in `method_missing'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/extensions/action_mailer.rb:20:in `perform'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/processor.rb:43:in `block (3 levels) in process'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:79:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:79:in `block in invoke'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/server/timeout.rb:11:in `block in call'
/app/vendor/ruby-1.9.3/lib/ruby/1.9.1/timeout.rb:68:in `timeout'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/server/timeout.rb:10:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:81:in `block in invoke'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:81:in `block in invoke'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/server/retry_jobs.rb:49:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:81:in `block in invoke'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/logging.rb:22:in `with_context'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:81:in `block in invoke'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:84:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/middleware/chain.rb:84:in `invoke'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/processor.rb:42:in `block (2 levels) in process'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/processor.rb:77:in `stats'
/app/vendor/bundle/ruby/1.9.1/gems/sidekiq-2.6.0/lib/sidekiq/processor.rb:41:in `block in process'
/app/vendor/bundle/ruby/1.9.1/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in `public_send'
/app/vendor/bundle/ruby/1.9.1/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in `dispatch'
/app/vendor/bundle/ruby/1.9.1/gems/celluloid-0.12.4/lib/celluloid/future.rb:18:in `block in initialize'
/app/vendor/bundle/ruby/1.9.1/gems/celluloid-0.12.4/lib/celluloid/internal_pool.rb:48:in `call'
/app/vendor/bundle/ruby/1.9.1/gems/celluloid-0.12.4/lib/celluloid/internal_pool.rb:48:in `block in create'

The weird thing is that they happen, and at the first retry they're managed correctly. I don't think it's an app problem (at line 16 it just set the user with: @user = message.user), but more a Sidekiq problem somewhere

The job's params are:

{ "retry" : "true", "queue" : "default", "timeout" : "30", "class" : "Sidekiq::Extensions::DelayedMailer", "args" : { "0" : "--- - !ruby/class 'Notifier' - :new_message - - 7 ", } "jid" : "b5ea7b43f38d78dede01f63b", "error_message" : "wrong number of arguments(1 for 0)", "error_class" : "ArgumentError", "failed_at" : "2012-12-27 03:40:27 UTC", "retry_count" : "0", }
Owner

mperham commented Dec 28, 2012

I'm pretty sure this is an actual bug in Rails. We see it at The Clymb regularly too. I don't have a solution for you and as you note it seems to go away when retried.

NZKoz commented Dec 28, 2012

Seems like it could be a bug in rails to me too, however it's unlikely to be tracked down unless you can conclusively prove that your models are all being eagerly loaded.

define_readers shouldn't be being called when your app is in-flight, so either your mailer is doing something 'weird' that's making that happen, or some part of rails' code is lazily generating the readers when it should be doing those eagerly.

xdmx commented Dec 28, 2012

It's probably because of it then.... this is what the mailer is doing:

  def new_message(message_id)
    headers["X-SMTPAPI"] = '{"category": "New message"}'
    @message = Message.find(message_id)
    @user = @message.user
    mail to: @user.name_and_email, subject: 'You have received a new message!'
  end

A Message.find(message_id, includes: :user) (or Message.where(id: message_id).includes(:user).first ) could probably help... I'm closing this for now and trying to change it in all the mailers. I'll reopen this if it'll still throw that exception

@xdmx xdmx closed this Dec 28, 2012

@xdmx I wouldn't be too quick to close it - I've been looking at the eager autoloading of the various Active Record components this morning and I'm pretty certain it's a Rails bug.

What appears to be happening is a race condition in the autoloading of AssociationScope - a second thread is accessing the constant before the definition has finished loading. This is the classic example of how autoload is not threadsafe and is why the Rails eager autoloading mechanism was written. The way it works in Rails 3.2 is that an initializer block loads all the constants marked for eager loading by using ActiveSupport::Autoload.eager_load! if the config.preload_frameworks setting is true. This method iterates over a list of paths and explicitly requires them.

The problem I think exists is that where you have nested constants marked for eager autoloading - the nested constants are added to the list when the parent is required but eager_autoload! wont see them. For example AssociationScope is marked for eager autoloading inside ActiveRecord::Associations but that's marked for eager autoloading itself.

You can see this in action by booting up irb:

>> require 'active_record'
=> true
>> ActiveRecord.autoloads.key?(:Associations)
=> true
>> ActiveRecord.autoloads.key?(:AssociationScope)
=> false
>> ActiveSupport::Autoload.eager_autoload!
=> [...]
>> ActiveRecord.autoloads.key?(:AssociationScope)
=> true

You can work around the bug by triggering the autoload before Sidekiq starts processing jobs.

This change suggests the problem is fixed on the Rails master branch.

Owner

mperham commented Dec 29, 2012

@NZKoz Does @pixeltrix's assessment make sense?

@mperham mperham reopened this Dec 29, 2012

Owner

mperham commented Dec 29, 2012

@xdmx Can you manually require 'active_record/associations/association_scope' in an initializer and see if the error disappears?

NZKoz commented Dec 29, 2012

@mperham seems like @pixeltrix is entirely on to it. Still unclear to me why that constant hasn't been referenced until after the model is required, however that's mostly because I've only glanced at the source.

@NZKoz AssociationScope isn't referenced until an actual query through an association is called, so unless something references ActiveRecord::Associations before eager_load! then it's not added to the list. Easiest way to demonstrate this is by requiring ActiveRecord::Base before eager loading.

>> require 'active_record'
>> ActiveRecord.autoloads.key?(:AssociationScope)
=> false
>> require 'active_record/base'
>> ActiveRecord.autoloads.key?(:AssociationScope)
=> true

A quick workaround would be to call ActiveSupport::Autoload.eager_autoload! again before processing jobs.

@NZKoz also the AssociationScope instance is lazily created for reasons explained in the comment:

https://github.com/rails/rails/blob/3-2-stable/activerecord/lib/active_record/associations/association.rb#L90-L100

Owner

mperham commented Dec 31, 2012

Closing as this is not a Sidekiq issue; further discussion should go in rails/rails#7770

@mperham mperham closed this Dec 31, 2012

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment