Rails, Sidekiq, Redis on Heroku - something wrong

4
votes

I have a problem with my Rails app.

App based on Ruby on Rails with Sidekiq, Redis and deployed on Heroku. I don't know why my worker doesn't work on Heroku. I think something is wrong in my settings.

config/initializers/sidekiq.rb

Sidekiq.configure_server do |config|
  config.redis = { url: 'redis://localhost:6379/0' }
  schedule_file = "config/sidekiq.yml"
  if File.exists?(schedule_file)
    Sidekiq::Cron::Job.load_from_hash YAML.load_file(schedule_file)
  end
end

Sidekiq.configure_client do |config|
  config.redis = { url: 'redis://localhost:6379/0' }
end

workers/my_worker.rb

class MyWorker

  include Sidekiq::Worker

  def perform
    ......
  end
end

config/sidekiq.yml

my_photos:
  cron: "30 3 */2 * *"
  class: "MyWorker"
  queue: default

Procfile

web: bundle exec rails server -p $PORT
worker: bundle exec sidekiq -e production

application.rb includes line:

config.active_job.queue_adapter = :sidekiq

I have installed Redis To Go on Heroku.

Heroku config:

REDISTOGO_URL: redis://redistogo:2085d9ff......
REDIS_PROVIDER: REDISTOGO_URL
.
.
.

Everything works fine on localhost development and production mode (worker too) but on Heroku worker doesn't work well.

Some errors:

Error connecting to Redis on localhost:6379 (Errno::ECONNREFUSED)

heroku ps in console displays:

=== web (Free): bundle exec rails server -p $PORT (1)
web.1: up 2019/09/18 16:57:03 +0200

=== worker (Free): bundle exec sidekiq -e production (1)
worker.1: crashed 2019/09/18 17:27:42 +0200

Yes, I restarted Heroku.

***

Heroku logs after change config.redis to ENV['REDISTOGO_URL'] in sidekiq.rb

2019-09-18T16:29:30.621771+00:00 app[web.1]: => Booting Puma
2019-09-18T16:29:30.621789+00:00 app[web.1]: => Rails 5.2.3 application starting in production
2019-09-18T16:29:30.62179+00:00 app[web.1]: => Run `rails server -h` for more startup options
2019-09-18T16:29:30.621791+00:00 app[web.1]: Puma starting in single mode...
2019-09-18T16:29:30.621792+00:00 app[web.1]: * Version 3.12.1 (ruby 2.6.1-p33), codename: Llamas in Pajamas
2019-09-18T16:29:30.621793+00:00 app[web.1]: * Min threads: 5, max threads: 5
2019-09-18T16:29:30.621796+00:00 app[web.1]: * Environment: production
2019-09-18T16:29:30.621797+00:00 app[web.1]: * Listening on tcp://0.0.0.0:42164
2019-09-18T16:29:30.621798+00:00 app[web.1]: Use Ctrl-C to stop
2019-09-18T16:29:30.621799+00:00 app[web.1]: I, [2019-09-18T16:29:30.621672 #4]  INFO -- : [2fa14d58-5519-456e-a527-9cf4ed462e86] Started GET "/dogs" for 195.136.56.0 at 2019-09-18 16:29:30 +0000
2019-09-18T16:29:30.62264+00:00 app[web.1]: I, [2019-09-18T16:29:30.622583 #4]  INFO -- : [2fa14d58-5519-456e-a527-9cf4ed462e86] Processing by DogsController#index as HTML
2019-09-18T16:29:30.683193+00:00 app[web.1]: D, [2019-09-18T16:29:30.683061 #4] DEBUG -- : [2fa14d58-5519-456e-a527-9cf4ed462e86]   User Load (1.2ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
2019-09-18T16:29:30.704369+00:00 app[web.1]: I, [2019-09-18T16:29:30.704248 #4]  INFO -- : [2fa14d58-5519-456e-a527-9cf4ed462e86]   Rendering dogs/index.html.erb within layouts/application
2019-09-18T16:29:30.708316+00:00 app[web.1]: D, [2019-09-18T16:29:30.708230 #4] DEBUG -- : [2fa14d58-5519-456e-a527-9cf4ed462e86]   Dog Load (1.5ms)  SELECT  "dogs".* FROM "dogs" ORDER BY created_at DESC LIMIT $1 OFFSET $2  [["LIMIT", 24], ["OFFSET", 0]]
2019-09-18T16:29:30.715597+00:00 app[web.1]: I, [2019-09-18T16:29:30.715534 #4]  INFO -- : [2fa14d58-5519-456e-a527-9cf4ed462e86]   Rendered dogs/index.html.erb within layouts/application (11.2ms)
2019-09-18T16:29:30.718909+00:00 app[web.1]: I, [2019-09-18T16:29:30.718852 #4]  INFO -- : [2fa14d58-5519-456e-a527-9cf4ed462e86] Completed 200 OK in 96ms (Views: 13.8ms | ActiveRecord: 28.1ms)
2019-09-18T16:29:32.200757+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=myappaddress.herokuapp.com request_id=77ecb62d-e044-4eee-be8c-a0f0749af788 fwd="195.136.56.0" dyno=web.1 connect=0ms service=1ms status=200 bytes=143 protocol=https
2019-09-18T16:29:32.047254+00:00 app[web.1]: I, [2019-09-18T16:29:32.047168 #4]  INFO -- : [2bfdeee1-c974-4a9e-97ac-659f58d14a0d] Started GET "/dogs" for 195.136.56.0 at 2019-09-18 16:29:32 +0000
2019-09-18T16:29:32.047891+00:00 app[web.1]: I, [2019-09-18T16:29:32.047835 #4]  INFO -- : [2bfdeee1-c974-4a9e-97ac-659f58d14a0d] Processing by DogsController#index as HTML
2019-09-18T16:29:32.051783+00:00 app[web.1]: D, [2019-09-18T16:29:32.051719 #4] DEBUG -- : [2bfdeee1-c974-4a9e-97ac-659f58d14a0d]   User Load (1.0ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
2019-09-18T16:29:32.053487+00:00 app[web.1]: I, [2019-09-18T16:29:32.053403 #4]  INFO -- : [2bfdeee1-c974-4a9e-97ac-659f58d14a0d]   Rendering dogs/index.html.erb within layouts/application
2019-09-18T16:29:32.054812+00:00 app[web.1]: D, [2019-09-18T16:29:32.054749 #4] DEBUG -- : [2bfdeee1-c974-4a9e-97ac-659f58d14a0d]   Dog Load (1.0ms)  SELECT  "dogs".* FROM "dogs" ORDER BY created_at DESC LIMIT $1 OFFSET $2  [["LIMIT", 24], ["OFFSET", 0]]
2019-09-18T16:29:32.055346+00:00 app[web.1]: I, [2019-09-18T16:29:32.055289 #4]  INFO -- : [2bfdeee1-c974-4a9e-97ac-659f58d14a0d]   Rendered dogs/index.html.erb within layouts/application (1.8ms)
2019-09-18T16:29:32.056958+00:00 app[web.1]: I, [2019-09-18T16:29:32.056901 #4]  INFO -- : [2bfdeee1-c974-4a9e-97ac-659f58d14a0d] Completed 200 OK in 9ms (Views: 2.7ms | ActiveRecord: 1.9ms)
2019-09-18T16:29:32.059156+00:00 heroku[router]: at=info method=GET path="/dogs" host=myappaddress.herokuapp.com request_id=2bfdeee1-c974-4a9e-97ac-659f58d14a0d fwd="195.136.56.0" dyno=web.1 connect=0ms service=14ms status=200 bytes=2828 protocol=https
2019-09-18T16:29:33.373311+00:00 heroku[router]: at=info method=GET path="/dogs" host=myappaddress.herokuapp.com request_id=953acff7-12c6-4876-99eb-57686a8e054b fwd="195.136.56.0" dyno=web.1 connect=0ms service=15ms status=200 bytes=2850 protocol=https
2019-09-18T16:29:33.360115+00:00 app[web.1]: I, [2019-09-18T16:29:33.360015 #4]  INFO -- : [953acff7-12c6-4876-99eb-57686a8e054b] Started GET "/dogs" for 195.136.56.0 at 2019-09-18 16:29:33 +0000
2019-09-18T16:29:33.360839+00:00 app[web.1]: I, [2019-09-18T16:29:33.360763 #4]  INFO -- : [953acff7-12c6-4876-99eb-57686a8e054b] Processing by DogsController#index as HTML
2019-09-18T16:29:33.364996+00:00 app[web.1]: D, [2019-09-18T16:29:33.364927 #4] DEBUG -- : [953acff7-12c6-4876-99eb-57686a8e054b]   User Load (0.9ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
2019-09-18T16:29:33.36734+00:00 app[web.1]: I, [2019-09-18T16:29:33.367264 #4]  INFO -- : [953acff7-12c6-4876-99eb-57686a8e054b]   Rendering dogs/index.html.erb within layouts/application
2019-09-18T16:29:33.368712+00:00 app[web.1]: D, [2019-09-18T16:29:33.368637 #4] DEBUG -- : [953acff7-12c6-4876-99eb-57686a8e054b]   Dog Load (1.0ms)  SELECT  "dogs".* FROM "dogs" ORDER BY created_at DESC LIMIT $1 OFFSET $2  [["LIMIT", 24], ["OFFSET", 0]]
2019-09-18T16:29:33.370049+00:00 app[web.1]: I, [2019-09-18T16:29:33.369947 #4]  INFO -- : [953acff7-12c6-4876-99eb-57686a8e054b]   Rendered dogs/index.html.erb within layouts/application (2.6ms)
2019-09-18T16:29:33.371552+00:00 app[web.1]: I, [2019-09-18T16:29:33.371479 #4]  INFO -- : [953acff7-12c6-4876-99eb-57686a8e054b] Completed 200 OK in 10ms (Views: 2.8ms | ActiveRecord: 1.9ms)
2019-09-18T16:29:33.506177+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=myappaddress.herokuapp.com request_id=11c98ea8-5df1-4a9f-9a5a-fb609bf1f9b1 fwd="195.136.56.0" dyno=web.1 connect=0ms service=1ms status=200 bytes=143 protocol=https
2019-09-18T16:29:37.398927+00:00 heroku[web.1]: source=web.1 dyno=heroku.146423817.b27d01ed-7668-4c8c-9451-68f3c0f447c7 sample#memory_total=143.53MB sample#memory_rss=104.20MB sample#memory_cache=39.34MB sample#memory_swap=0.00MB sample#memory_pgpgin=51710pages sample#memory_pgpgout=14966pages sample#memory_quota=512.00MB
2019-09-18T16:29:54.267638+00:00 app[api]: Starting process with command `bin/rails console` by user [email protected]
2019-09-18T16:29:55.487272+00:00 heroku[router]: at=info method=GET path="/dogs" host=myappaddress.herokuapp.com request_id=4318929d-efc2-4ad1-ad0d-c0a9ae155a8c fwd="195.136.56.0" dyno=web.1 connect=0ms service=14ms status=200 bytes=2840 protocol=https
2019-09-18T16:29:55.474089+00:00 app[web.1]: I, [2019-09-18T16:29:55.473957 #4]  INFO -- : [4318929d-efc2-4ad1-ad0d-c0a9ae155a8c] Started GET "/dogs" for 195.136.56.0 at 2019-09-18 16:29:55 +0000
2019-09-18T16:29:55.475425+00:00 app[web.1]: I, [2019-09-18T16:29:55.475356 #4]  INFO -- : [4318929d-efc2-4ad1-ad0d-c0a9ae155a8c] Processing by DogsController#index as HTML
2019-09-18T16:29:55.478716+00:00 app[web.1]: D, [2019-09-18T16:29:55.478637 #4] DEBUG -- : [4318929d-efc2-4ad1-ad0d-c0a9ae155a8c]   User Load (1.1ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
2019-09-18T16:29:55.480624+00:00 app[web.1]: I, [2019-09-18T16:29:55.480549 #4]  INFO -- : [4318929d-efc2-4ad1-ad0d-c0a9ae155a8c]   Rendering dogs/index.html.erb within layouts/application
2019-09-18T16:29:55.481962+00:00 app[web.1]: D, [2019-09-18T16:29:55.481884 #4] DEBUG -- : [4318929d-efc2-4ad1-ad0d-c0a9ae155a8c]   Dog Load (1.0ms)  SELECT  "dogs".* FROM "dogs" ORDER BY created_at DESC LIMIT $1 OFFSET $2  [["LIMIT", 24], ["OFFSET", 0]]
2019-09-18T16:29:55.483895+00:00 app[web.1]: I, [2019-09-18T16:29:55.483823 #4]  INFO -- : [4318929d-efc2-4ad1-ad0d-c0a9ae155a8c]   Rendered dogs/index.html.erb within layouts/application (3.2ms)
2019-09-18T16:29:55.484818+00:00 app[web.1]: I, [2019-09-18T16:29:55.484747 #4]  INFO -- : [4318929d-efc2-4ad1-ad0d-c0a9ae155a8c] Completed 200 OK in 9ms (Views: 3.4ms | ActiveRecord: 2.0ms)
2019-09-18T16:29:55.629132+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=myappaddress.herokuapp.com request_id=d2dc2b32-bf0c-42b0-b0ee-e688014a1858 fwd="195.136.56.0" dyno=web.1 connect=0ms service=2ms status=200 bytes=143 protocol=https
2019-09-18T16:29:56.6973+00:00 heroku[router]: at=info method=GET path="/dogs" host=myappaddress.herokuapp.com request_id=22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf fwd="195.136.56.0" dyno=web.1 connect=1ms service=14ms status=200 bytes=2850 protocol=https
2019-09-18T16:29:56.832815+00:00 heroku[router]: at=info method=GET path="/favicon.ico" host=myappaddress.herokuapp.com request_id=d76015da-381e-422d-8cfa-60d277ead4b8 fwd="195.136.56.0" dyno=web.1 connect=0ms service=1ms status=200 bytes=143 protocol=https
2019-09-18T16:29:56.683482+00:00 app[web.1]: I, [2019-09-18T16:29:56.683384 #4]  INFO -- : [22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf] Started GET "/dogs" for 195.136.56.0 at 2019-09-18 16:29:56 +0000
2019-09-18T16:29:56.684878+00:00 app[web.1]: I, [2019-09-18T16:29:56.684813 #4]  INFO -- : [22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf] Processing by DogsController#index as HTML
2019-09-18T16:29:56.688315+00:00 app[web.1]: D, [2019-09-18T16:29:56.688210 #4] DEBUG -- : [22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf]   User Load (1.1ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
2019-09-18T16:29:56.690898+00:00 app[web.1]: I, [2019-09-18T16:29:56.690833 #4]  INFO -- : [22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf]   Rendering dogs/index.html.erb within layouts/application
2019-09-18T16:29:56.692612+00:00 app[web.1]: D, [2019-09-18T16:29:56.692550 #4] DEBUG -- : [22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf]   Dog Load (1.1ms)  SELECT  "dogs".* FROM "dogs" ORDER BY created_at DESC LIMIT $1 OFFSET $2  [["LIMIT", 24], ["OFFSET", 0]]
2019-09-18T16:29:56.693963+00:00 app[web.1]: I, [2019-09-18T16:29:56.693898 #4]  INFO -- : [22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf]   Rendered dogs/index.html.erb within layouts/application (2.9ms)
2019-09-18T16:29:56.695684+00:00 app[web.1]: I, [2019-09-18T16:29:56.695620 #4]  INFO -- : [22b98e70-0f07-4ac8-a93e-ba2d0df3ccbf] Completed 200 OK in 11ms (Views: 3.9ms | ActiveRecord: 2.2ms)
2019-09-18T16:29:58.295567+00:00 app[web.1]: I, [2019-09-18T16:29:58.295456 #4]  INFO -- : [98a19c4a-cdda-4112-bb38-5869ede78b49] Started GET "/dogs" for 195.136.56.0 at 2019-09-18 16:29:58 +0000
2019-09-18T16:29:58.297473+00:00 app[web.1]: I, [2019-09-18T16:29:58.297393 #4]  INFO -- : [98a19c4a-cdda-4112-bb38-5869ede78b49] Processing by DogsController#index as HTML
2019-09-18T16:29:58.301213+00:00 app[web.1]: D, [2019-09-18T16:29:58.301128 #4] DEBUG -- : [98a19c4a-cdda-4112-bb38-5869ede78b49]   User Load (1.0ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["id", 1], ["LIMIT", 1]]
2019-09-18T18:45:05.749467+00:00 heroku[web.1]: source=web.1 dyno=heroku.146423817.2c282eb9-e271-478a-a164-ab1ee7b48d15 sample#load_avg_1m=0.35
2019-09-18T18:45:05.779083+00:00 heroku[web.1]: source=web.1 dyno=heroku.146423817.2c282eb9-e271-478a-a164-ab1ee7b48d15 sample#memory_total=141.63MB sample#memory_rss=102.39MB sample#memory_cache=39.24MB sample#memory_swap=0.00MB sample#memory_pgpgin=51236pages sample#memory_pgpgout=14978pages sample#memory_quota=512.00MB

Sidekiq logs:

2019-09-18T21:42:34.875Z pid=2604 tid=gmvw62cjk class=FlickrWorker jid=d4d37c3accf6190b8193758d elapsed=5.561 INFO: fail
2019-09-18T21:42:34.875Z pid=2604 tid=gmvw62cjk WARN: {"context":"Job raised exception","job":{"queue":"default","args":[],"class":"FlickrWorker","retry":true,"jid":"d4d37c3accf6190b8193758d","created_at":1568805601.6104372,"enqueued_at":1568842949.307712,"error_message":"could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use","error_class":"ActiveRecord::ConnectionTimeoutError","failed_at":1568805607.190152,"retry_count":5,"retried_at":1568806408.705434},"jobstr":"{\"queue\":\"default\",\"args\":[],\"class\":\"FlickrWorker\",\"retry\":true,\"jid\":\"d4d37c3accf6190b8193758d\",\"created_at\":1568805601.6104372,\"enqueued_at\":1568842949.307712,\"error_message\":\"could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use\",\"error_class\":\"ActiveRecord::ConnectionTimeoutError\",\"failed_at\":1568805607.190152,\"retry_count\":5,\"retried_at\":1568806408.705434}"}
2019-09-18T21:42:34.875Z pid=2604 tid=gmvw62cjk WARN: ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
2019-09-18T21:42:34.875Z pid=2604 tid=gmvw62cjk WARN: /home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:201:in `block in wait_poll'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `loop'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `wait_poll'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:151:in `internal_poll'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:277:in `internal_poll'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `block in poll'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/2.6.0/monitor.rb:230:in `mon_synchronize'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:155:in `synchronize'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `poll'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:799:in `acquire_connection'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:523:in `checkout'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:382:in `connection'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:1014:in `retrieve_connection'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_handling.rb:118:in `retrieve_connection'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_handling.rb:90:in `connection'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/calculations.rb:196:in `block in pluck'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation.rb:584:in `skip_query_cache_if_necessary'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/calculations.rb:196:in `pluck'
/home/miro/ror/my-app/app/workers/flickr_worker.rb:11:in `block in perform'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/flickraw-0.9.10/lib/flickraw/response.rb:42:in `block in each'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/flickraw-0.9.10/lib/flickraw/response.rb:42:in `each'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/flickraw-0.9.10/lib/flickraw/response.rb:42:in `each'
/home/miro/ror/my-app/app/workers/flickr_worker.rb:11:in `reject'
/home/miro/ror/my-app/app/workers/flickr_worker.rb:11:in `perform'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:193:in `execute_job'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:161:in `block (2 levels) in process'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/middleware/chain.rb:134:in `invoke'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:160:in `block in process'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:133:in `block (6 levels) in dispatch'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/job_retry.rb:107:in `local'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:132:in `block (5 levels) in dispatch'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/rails.rb:43:in `block in call'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.3/lib/active_support/execution_wrapper.rb:87:in `wrap'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.3/lib/active_support/reloader.rb:73:in `block in wrap'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.3/lib/active_support/execution_wrapper.rb:87:in `wrap'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.3/lib/active_support/reloader.rb:72:in `wrap'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/rails.rb:42:in `call'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:128:in `block (4 levels) in dispatch'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:254:in `stats'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:123:in `block (3 levels) in dispatch'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/job_logger.rb:13:in `call'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:122:in `block (2 levels) in dispatch'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/job_retry.rb:75:in `global'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:121:in `block in dispatch'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/logger.rb:16:in `with_context'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/job_logger.rb:27:in `with_job_hash_context'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:120:in `dispatch'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:159:in `process'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:78:in `process_one'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/processor.rb:68:in `run'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/util.rb:17:in `watchdog'
/home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/util.rb:26:in `block in safe_thread'
2019-09-18T21:42:34.876Z pid=2604 tid=ov922z8j8 class=FlickrWorker jid=73817a6886c934cc0e57d83c INFO: start
2019-09-18T21:42:34.907Z pid=2604 tid=gmvw62ctw class=FlickrWorker jid=f7a4c1d1e5da2939db1202ae elapsed=5.591 INFO: fail
2019-09-18T21:42:34.907Z pid=2604 tid=gmvw62ctw WARN: {"context":"Job raised exception","job":{"queue":"default","args":[],"class":"FlickrWorker","retry":true,"jid":"f7a4c1d1e5da2939db1202ae","created_at":1568806211.883125,"enqueued_at":1568842949.3102987,"error_message":"could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use","error_class":"ActiveRecord::ConnectionTimeoutError","failed_at":1568806217.393686,"retry_count":5,"retried_at":1568806883.9672208},"jobstr":"{\"queue\":\"default\",\"args\":[],\"class\":\"FlickrWorker\",\"retry\":true,\"jid\":\"f7a4c1d1e5da2939db1202ae\",\"created_at\":1568806211.883125,\"enqueued_at\":1568842949.3102987,\"error_message\":\"could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use\",\"error_class\":\"ActiveRecord::ConnectionTimeoutError\",\"failed_at\":1568806217.393686,\"retry_count\":5,\"retried_at\":1568806883.9672208}"}
2019-09-18T21:42:34.907Z pid=2604 tid=gmvw62ctw WARN: ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
2019-09-18T21:42:34.908Z pid=2604 tid=gmvw62ctw WARN: /home/miro/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:201:in `block in wait_poll'

heroku logs | grep worker

2019-09-18T17:31:17.211968+00:00 heroku[worker.1]: Starting process with command `bundle exec sidekiq -e production`
2019-09-18T17:31:17.859475+00:00 heroku[worker.1]: State changed from starting to up
2019-09-18T17:31:21.738484+00:00 app[worker.1]: pid=4 tid=gq4np076o INFO: Booting Sidekiq 6.0.0 with redis options {:url=>"redis://redistogo:[email protected]:11228/", :id=>"Sidekiq-server-PID-4"}
2019-09-18T17:31:21.766614+00:00 app[worker.1]: pid=4 tid=gq4np076o INFO: Cron Jobs - add job with name: flickr_photos
2019-09-18T17:31:23.288563+00:00 app[worker.1]: pid=4 tid=gq4np076o INFO: Running in ruby 2.6.1p33 (2019-01-30 revision 66950) [x86_64-linux]
2019-09-18T17:31:23.288599+00:00 app[worker.1]: pid=4 tid=gq4np076o INFO: See LICENSE and the LGPL-3.0 for licensing details.
2019-09-18T17:31:23.288602+00:00 app[worker.1]: pid=4 tid=gq4np076o INFO: Upgrade to Sidekiq Pro for more features and support: http://sidekiq.org
2019-09-18T17:31:23.289887+00:00 app[worker.1]: You are using Redis v3.2.12, Sidekiq requires Redis v4.0.0 or greater
2019-09-18T17:31:23.289931+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/sidekiq-6.0.0/lib/sidekiq/cli.rb:59:in `run'
2019-09-18T17:31:23.289932+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/sidekiq-6.0.0/bin/sidekiq:12:in `<top (required)>'
2019-09-18T17:31:23.289933+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/bin/sidekiq:23:in `load'
2019-09-18T17:31:23.289934+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/bin/sidekiq:23:in `<top (required)>'
2019-09-18T17:31:23.289935+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/cli/exec.rb:74:in `load'
2019-09-18T17:31:23.289936+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/cli/exec.rb:74:in `kernel_load'
2019-09-18T17:31:23.289937+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/cli/exec.rb:28:in `run'
2019-09-18T17:31:23.289938+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/cli.rb:465:in `exec'
2019-09-18T17:31:23.289939+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
2019-09-18T17:31:23.28994+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
2019-09-18T17:31:23.289941+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
2019-09-18T17:31:23.289943+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/cli.rb:27:in `dispatch'
2019-09-18T17:31:23.289943+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
2019-09-18T17:31:23.289944+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/cli.rb:18:in `start'
2019-09-18T17:31:23.289945+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/exe/bundle:30:in `block in <top (required)>'
2019-09-18T17:31:23.289946+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/lib/bundler/friendly_errors.rb:124:in `with_friendly_errors'
2019-09-18T17:31:23.289947+00:00 app[worker.1]: /app/vendor/bundle/ruby/2.6.0/gems/bundler-2.0.2/exe/bundle:22:in `<top (required)>'
2019-09-18T17:31:23.289948+00:00 app[worker.1]: /app/bin/bundle:3:in `load'
2019-09-18T17:31:23.289949+00:00 app[worker.1]: /app/bin/bundle:3:in `<main>'
2019-09-18T17:31:23.357667+00:00 heroku[worker.1]: Process exited with status 1
2019-09-18T17:31:23.411452+00:00 heroku[worker.1]: State changed from up to crashed
3
ruby-on-railsrubyherokusidekiq

3 Answers

14
votes

John is correct, Sidekiq 6 requires at least Redis 4, but Redis To Go has not updated from version 3.

Instead of downgrading to meet the requirements of Redis To Go i would recommended moving dependencies.

Since you are using Heroku, two popular alternatives are Heroku Redis and Redis Cloud.

Since Redis 4 was released 2.5 years ago and Redis 5 is already released, its safe to say that Redis To Go is falling behind and you should strongly consider moving to a dependency that gets updated more frequently.

Neglecting to do so will be more difficult in the long run.

9
votes

Seems to be a versioning issue:

Sidekiq 6 requires Redis 4, but RedisToGo as provided by Heroku is still using Redis 3.x I stepped around the problem by specifying in my Gemfile:

gem 'sidekiq', '5.2.7'

2
votes

You have your redis URL hardcoded in config/initializers/sidekiq.rb

Instead of:

config.redis = { url: 'redis://localhost:6379/0' }

use

config.redis = { url: ENV['REDIS_URL'] }

and ensure REDIS_URL set correctly on heroku (maybe set it manually or maybe the add-on or heroku takes care of it, I don't remember).