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.

Sign up for GitHub

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

Jump to bottom

NoMethodError: undefined method `call' for "fd941a28e3588387ad7ef2ca":String #1731

Closed
ghost opened this issue May 22, 2014 · 12 comments
Closed

NoMethodError: undefined method `call' for "fd941a28e3588387ad7ef2ca":String #1731

ghost opened this issue May 22, 2014 · 12 comments

Comments

@ghost
Copy link

ghost commented May 22, 2014

Hi,

We are facing weird error in here, we try to run load test with Siege for 10hours.
We had 4 errors all like this, ex:
NoMethodError: undefined method `call' for "fd941a28e3588387ad7ef2ca":String

Inside perform method we try to read the retry_count. This is the code how we do it:

worker = Sidekiq::Workers.new.find(job_id)
retry_count = worker.first.last["payload"]["retry_count"]

Total transaction 303870 jobs inserted into sidekiq within 10 hours and we have 4 dead job.
@mperham
Copy link
Collaborator

mperham commented May 22, 2014

Do you have a full backtrace?

@parhamr
Copy link

parhamr commented May 23, 2014

I’m seeing a similar error with Rails 3.0.20, and here is the full backtrace…

2014-05-23T18:36:08Z 21342 TID-1e1oy6 ERROR: Sidekiq::Processor crashed!
NoMethodError: undefined method `:ending' for "RedactedMailer":String
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/extensions/action_mailer.rb:17:in `perform'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:49:in `block (3 levels) in process'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:122:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:122:in `block in invoke'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/newrelic_rpm-3.8.1.221/lib/new_relic/agent/instrumentation/sidekiq.rb:32:in `block in call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/newrelic_rpm-3.8.1.221/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:357:in `perform_action_with_newrelic_trace'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/newrelic_rpm-3.8.1.221/lib/new_relic/agent/instrumentation/sidekiq.rb:26:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/retry_jobs.rb:62:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/logging.rb:22:in `with_context'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/server/logging.rb:7:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:127:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/middleware/chain.rb:127:in `invoke'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:48:in `block (2 levels) in process'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:108:in `stats'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:47:in `block in process'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/calls.rb:67:in `dispatch'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/future.rb:14:in `block in new'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/thread_handle.rb:13:in `block in initialize'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/internal_pool.rb:100:in `call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/internal_pool.rb:100:in `block in create'
        (celluloid):0:in `remote procedure call'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/future.rb:104:in `value'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/future.rb:68:in `value'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid.rb:456:in `defer'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:84:in `do_defer'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/sidekiq-2.17.7/lib/sidekiq/processor.rb:37:in `process'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
        /data/redacted/shared/bundled_gems/ruby/1.9.1/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'

The RedactedMailer is called like this:

RedactedMailer.delay(:retry => false, :queue => 'mailers').ending(id, user.id)

This is Ruby 1.9.3-p484, so I’ll try updating to 1.9.3-p547. Gems…

DEPENDENCIES
  activemerchant (~> 1.20)
  activerecord-mysql2-adapter
  acts-as-taggable-on (~> 2.2)
  awesome_print
  aws-s3
  aws-sdk
  bluecloth
  capybara
  capybara-webkit
  clockwork
  connection_pool
  dalli
  database_cleaner
  devise (~> 1.1.9)
  engineyard (~> 1.3.33)
  engineyard-serverside-adapter
  ey_config
  factory_girl_rails
  faker
  fb_graph (~> 2.6)
  friendly_id (~> 3.1)
  geokit-rails
  growl
  guard
  guard-livereload
  guard-rspec
  guard-spork
  haml-rails
  headless
  hirb
  hpricot
  i18n (= 0.5.0)
  interactive_editor
  itslog
  jammit
  json_spec
  kgio (~> 2.9.2)
  launchy
  libnotify
  linguistics
  memcache-client
  mobile-fu
  mysql2 (~> 0.3.0)
  newrelic_rpm
  nifty-generators
  omniauth (~> 1.1.4)
  omniauth-facebook
  omniauth-linkedin-oauth2
  omniauth-twitter
  paperclip (~> 2.3)
  possessive
  prickle
  pry
  rack (~> 1.2.2)
  rack-ssl-enforcer
  rails (~> 3.0.19)
  rails3-generators
  rb-fsevent
  rb-inotify
  redis (~> 3.0)
  redis-objects
  rspec-rails (~> 2.8.0)
  ruby_parser
  sanitize
  sass
  shoulda
  sidekiq
  simplecov
  sinatra
  sitemap_generator
  slim
  spork-rails
  sprockets
  terminal-notifier-guard
  thin
  thinking-sphinx (~> 2.0.10)
  thinking-sphinx-rspec-matchers
  timecop
  unicorn
  validates_timeliness
  vcr
  webmock
  wepay!
  will_paginate
  wirble
  yajl-ruby
  yard

@parhamr
Copy link

parhamr commented May 23, 2014

This started when upgrading from 2.17.3 to 2.17.7.

@parhamr
Copy link

parhamr commented May 23, 2014

The issue persists after rolling back to Sidekiq 2.17.3 on 1.9.3-p547.

@parhamr
Copy link

parhamr commented May 23, 2014

(continuing to bisect until I find the culprit)

@seuros
Copy link
Collaborator

seuros commented May 23, 2014

@parhamr , remove new_relic and try again.

@parhamr
Copy link

parhamr commented May 23, 2014

@seuros bingo!

@parhamr parhamr mentioned this issue May 23, 2014
Closed
@parhamr
Copy link

parhamr commented May 23, 2014

Fixed with rollback to gem 'newrelic_rpm', '~> 3.7.3.204'. I’m comfortable with closing this, but maybe it’s useful to keep open for visibility until New Relic solves the problem.

@mperham
Copy link
Collaborator

mperham commented May 23, 2014

Any obvious causes in their changelog?

On May 23, 2014, at 14:00, Reid Parham notifications@github.com wrote:

Fixed with rollback to newrelic_rpm '~> 3.7.3.204'. I’m comfortable with closing this, but maybe it’s useful to keep open for visibility until New Relic solves the problem.

—
Reply to this email directly or view it on GitHub.

@parhamr
Copy link

parhamr commented May 23, 2014

@mperham this is my guess: https://github.com/newrelic/rpm/blob/87694a1a316efad5f31c2eca955d00c5ad29e02e/CHANGELOG#L5-L21; there’s nothing obvious in the changelog

@ghost
Copy link
Author

ghost commented May 28, 2014

Hi,

Sorry for late response, I have 2 questions regarding on this:

  1. What we are trying to do, we want to know the retry_count
worker = Sidekiq::Workers.new.find(job_id)
retry_count = worker.first.last["payload"]["retry_count"]

I don't know if this will be make sense to you or not, but is there any condition where when i try worker.first it will return empty or something else? So i can't do .last. Because sidekiq process only takes in millisecond right. (correct me if i'm wrong)

  1. Here are the log:
2014-05-21T09:04:55Z 24187 TID-ovrrd31ww WARN: undefined method `call' for "fd941a28e3588387ad7ef2ca":String
2014-05-21T09:04:55Z 24187 TID-ovrrd31ww WARN: /opt/railsapp/pato/app/services/sidekiq_service.rb:34:in `find'
/opt/railsapp/pato/app/services/sidekiq_service.rb:34:in `each'
/opt/railsapp/pato/app/services/sidekiq_service.rb:34:in `first'
/opt/railsapp/pato/app/services/sidekiq_service.rb:34:in `working!'
/opt/railsapp/pato/app/workers/http_post_service.rb:17:in `perform'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:50:in `block (2 levels) in process'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:122:in `call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:122:in `block in invoke'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/newrelic_rpm-3.8.0.218/lib/new_relic/agent/instrumentation/sidekiq.rb:32:in `block in call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/newrelic_rpm-3.8.0.218/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:336:in `perform_action_with_newrelic_trace'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/newrelic_rpm-3.8.0.218/lib/new_relic/agent/instrumentation/sidekiq.rb:23:in `call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/retry_jobs.rb:62:in `call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/logging.rb:22:in `with_context'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:124:in `block in invoke'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:127:in `call'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/middleware/chain.rb:127:in `invoke'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:49:in `block in process'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:92:in `stats'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/sidekiq-3.0.0/lib/sidekiq/processor.rb:48:in `process'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
/home/railsapp/.rbenv/versions/2.1.1/lib/ruby/gems/2.1.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create

Thanks

@mperham
Copy link
Collaborator

mperham commented May 28, 2014

  1. workers.first can return nil if there is nothing running.
  2. Have you seen the comments above? The cause seems to be something in the newrelic_rpm gem. Remove it and try again.

@mperham mperham closed this as completed Jun 7, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mperham @parhamr @seuros