Error fetching job: Waited 5 sec

615 views
Skip to first unread message

Mel Riffe

unread,
Sep 20, 2016, 7:59:22 PM9/20/16
to Sidekiq
I would greatly appreciate any help on this matter. I'm not sure where to turn.

My client and I are currently setting up production servers for their application. When I start Sidekiq it appears to start up fine, but then the log file has the following:

-----
2016-09-20T23:20:25.685Z 35595 TID-7winvo0 INFO: Running in ruby 2.2.5p319 (2016-04-26 revision 54774) [amd64-freebsd10]
2016-09-20T23:20:25.685Z 35595 TID-7winvo0 INFO: See LICENSE and the LGPL-3.0 for licensing details.
2016-09-20T23:20:25.685Z 35595 TID-7winvo0 INFO: Upgrade to Sidekiq Pro for more features and support: http://sidekiq.org
2016-09-20T23:20:25.687Z 35595 TID-7winvo0 DEBUG: Client Middleware:
2016-09-20T23:20:25.687Z 35595 TID-7winvo0 DEBUG: Server Middleware: Sidekiq::Middleware::Server::Logging, Sidekiq::Middleware::Server::RetryJobs, Sidekiq::Midd
leware::Server::ActiveRecord
2016-09-20T23:20:25.687Z 35595 TID-7winvo0 DEBUG: {:queues=>["paperclip", "paperclip", "critical", "default", "low"], :labels=>[], :concurrency=>20, :require=>"
.", :environment=>"production", :timeout=>8, :poll_interval_average=>nil, :average_scheduled_poll_interval=>15, :error_handlers=>[#<Sidekiq::ExceptionHandler::L
ogger:0x00000806db1268>], :lifecycle_events=>{:startup=>[], :quiet=>[], :shutdown=>[]}, :dead_max_jobs=>10000, :dead_timeout_in_seconds=>15552000, :verbose=>tru
e, :pidfile=>"tmp/pids/sidekiq.pid", :logfile=>"./log/sidekiq.log", "staging"=>{:concurrency=>10}, :strict=>false, :daemon=>true, :config_file=>"config/sidekiq.
yml", :tag=>"smeapi"}
2016-09-20T23:20:30.703Z 35595 TID-7yevk2c ERROR: Error fetching job: Waited 5 sec
2016-09-20T23:20:30.703Z 35595 TID-7yevk9k ERROR: Error fetching job: Waited 5 sec
2016-09-20T23:20:30.703Z 35595 TID-7yevjpk ERROR: Error fetching job: Waited 5 sec
2016-09-20T23:20:30.703Z 35595 TID-7yevk9k ERROR: /usr/local/lib/ruby/gems/2.2/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:85:in `block (2 lev
els) in pop'
[...snip...]
2016-09-20T23:20:35.730Z 35595 TID-7yex1d8 ERROR: heartbeat: Waited 5 sec
2016-09-20T23:20:39.020Z 35595 TID-7yevk9k INFO: Redis is online, 8.316293863 sec downtime
2016-09-20T23:20:41.247Z 35595 TID-7yevk2c INFO: Redis is online, 10.543917775 sec downtime
2016-09-20T23:20:41.460Z 35595 TID-7yevh84 INFO: Redis is online, 10.755361831 sec downtime
2016-09-20T23:20:42.016Z 35595 TID-7yex17o ERROR: Waited 5 sec
[...snip...]
2016-09-20T23:20:43.497Z 35595 TID-7yevjpk INFO: Redis is online, 12.793233622 sec downtime
2016-09-20T23:20:43.710Z 35595 TID-7yevg08 INFO: Redis is online, 13.005747585 sec downtime
2016-09-20T23:20:44.235Z 35595 TID-7yevid8 ERROR: Error fetching job: Waited 5 sec
2016-09-20T23:20:44.235Z 35595 TID-7yevid8 ERROR: /usr/local/lib/ruby/gems/2.2/gems/connection_pool-2.2.0/lib/connection_pool/timed_stack.rb:85:in `block (2 lev
[...snip...]
2016-09-20T23:20:45.747Z 35595 TID-7yex1d8 ERROR: heartbeat: Waited 5 sec
2016-09-20T23:20:46.266Z 35595 TID-7yevk2c ERROR: Error fetching job: Waited 5 sec
[...snip...]
2016-09-20T23:21:34.227Z 35595 TID-7winvo0 DEBUG: Got TERM signal
2016-09-20T23:21:34.227Z 35595 TID-7winvo0 INFO: Shutting down
2016-09-20T23:21:36.204Z 35595 TID-7yex1d8 ERROR: heartbeat: Waited 5 sec
2016-09-20T23:21:37.967Z 35595 TID-7yevfo0 INFO: Scheduler exiting...
2016-09-20T23:21:37.968Z 35595 TID-7winvo0 INFO: Terminating quiet workers
2016-09-20T23:21:39.698Z 35595 TID-7yex17o INFO: Scheduler exiting...
2016-09-20T23:21:40.231Z 35595 TID-7winvo0 INFO: Pausing to allow workers to finish...
2016-09-20T23:21:41.937Z 35595 TID-7yevh0c INFO: Redis is online, 55.557272953 sec downtime
2016-09-20T23:21:41.937Z 35595 TID-7yevh84 INFO: Redis is online, 55.444694123 sec downtime
2016-09-20T23:21:41.937Z 35595 TID-7yevk2c INFO: Redis is online, 55.671084527 sec downtime
2016-09-20T23:21:42.359Z 35595 TID-7winvo0 INFO: Bye!
-----

We have a staging server where Sidekiq runs fine. And, of course, there are some differences between the environments.

We have everything, except the database server, running on the Staging server: Sidekiq and Redis. In production, Redis is on another server.
We're running Ruby 2.2.4 on Staging; Ruby 2.2.5 on Production. We have the following gems:

-----
*** LOCAL GEMS ***

sidekiq (4.1.4)
sidekiq-cron (0.4.2)

*** LOCAL GEMS ***

redis (3.3.0)
redis-namespace (1.5.2)
-----

And yes I can't remember where I 'found' my initializer, but this is what I have:

-----
# config/initializer/sidekiq.rb
# Load the redis.yml configuration file
redis_config = YAML.load_file( "#{Rails.root}/config/redis.yml" )[Rails.env]

# Redis config
Redis.current = ConnectionPool.new(size: (Sidekiq.server? ? 15 : 1), timeout: 5) do
  Redis.new host: redis_config['host'], port: redis_config['port'], db: redis_config['database']
end

# Sidekiq config
Sidekiq.configure_client do |config|
  config.redis = Redis.current
end

Sidekiq.configure_server do |config|
  config.redis = Redis.current

  schedule_file = "#{Rails.root}/config/schedule.yml"
  if File.exists? schedule_file
    Sidekiq::Cron::Job.load_from_hash YAML.load_file( schedule_file )
  end
end
-----

And here are the YAML files:

-----
# config/redis.yml
default: &default
  host: -[REDACTED]-
  port: 6379
  database: 8

staging:
  <<: *default

production:
  <<: *default

# config/sidekiq.yml
---
:verbose: true
:concurrency: 5
:pidfile: tmp/pids/sidekiq.pid
:logfile: ./log/sidekiq.log

staging:
  :concurrency: 10

production:
  :concurrency: 20

:queues:
  - [paperclip,2]
  - critical
  - default
  - low
-----

Where do I even begin to start tracking this down? What could be causing these errors? Is there more information I can provide to help debug this?

Again, any assistance will be greatly appreciated.

Kind regards,
Mel

Mike Perham

unread,
Sep 20, 2016, 8:03:02 PM9/20/16
to sid...@googlegroups.com
Delete your initializer. It's all wrong.
--
You received this message because you are subscribed to the Google Groups "Sidekiq" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sidekiq+u...@googlegroups.com.
To post to this group, send email to sid...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/sidekiq/7f11b715-212b-4a4b-bb87-19a4413f8b81%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Mel Riffe

unread,
Sep 21, 2016, 9:14:42 AM9/21/16
to Sidekiq
While I truly appreciate the terseness of the message, I am left with more questions.

Are you implying I don't need an initializer? How is it wrong? What should it look like? How will Sidekiq::Cron get initialized?

--Mel

Mike Perham

unread,
Sep 21, 2016, 12:29:12 PM9/21/16
to sid...@googlegroups.com
Hi Mel, an initializer is necessary if you wish to change the defaults.  The documentation on how to configure the Redis connection is here:


If the docs do not help, please let us know so we can improve it.  I can't speak to sidekiq-cron since it's not my project.

Mike

To unsubscribe from this group and stop receiving emails from it, send an email to sidekiq+unsubscribe@googlegroups.com.

To post to this group, send email to sid...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.



--
Mike Perham – CEO, Contributed Systems
Smart, effective open source infrastructure for your apps.

Mel Riffe

unread,
Sep 21, 2016, 9:56:24 PM9/21/16
to Sidekiq
Thanks for the clarification and link.

I was able to define REDIS_URL and Sidekiq was happy.

I did add an initializer just for sidekiq-cron, and it's also happy.

I went with simplicity and skipped using ConnectionPool.

--Mel
Reply all
Reply to author
Forward
0 new messages