ConnectionTimeoutError when queueing jobs

[typeoneerror]

Unsure if this is a Sidekiq 4.x issue or related to influitive/apartment-sidekiq#9, but I thought I might try updating from the latest 3.x and seeing if the latest Sidekiq works for me. Gonna roll back to 3.x (everything listed below works great with the previous version) and stick with that, but I'm wondering if this is an issue or just something silly I'm doing.

To start, I'm using Sidekiq 4.0.2 and locally I have Redis 3.0.2. My initializer looks like so:

require 'sidekiq/web'

redis_config = Rails.configuration.x.redis
redis_url = "redis://#{redis_config['host']}:#{redis_config['port']}"
redis_options = { url: redis_url }

Sidekiq.configure_server do |config|
  config.redis = redis_options
end

Sidekiq.configure_client do |config|
  config.redis = redis_options
end

Sidekiq::Web.use(Rack::Auth::Basic) do |username, password|
  [username, password] == [Rails.application.secrets.sidekiq_username, Rails.application.secrets.sidekiq_password]
end unless Rails.env.development?

In the upgrade guide, I see "You must have a minimum of concurrency + 2 connections in your pool or Sidekiq will exit. When in doubt, let Sidekiq size the connection pool for you." I'm not sure if this relates here and I'm unsure if letting Sidekiq set the connection pool size for me happens without explicitly configuring.

Here's the trace when the error happens. Typically, the jobs work if it's just one just but if a job enqueues a different job, the error shows up:

21:59:23 worker.1 | 2016-01-14T05:59:23.653Z 42480 TID-ov6c4r79k DripContentJob JID-9cd3d4c8b1cfe2d050229ae1 INFO: start
21:59:28 worker.1 | 2016-01-14T05:59:28.655Z 42480 TID-ov6c4r79k DripContentJob JID-9cd3d4c8b1cfe2d050229ae1 INFO: fail: 5.002 sec
21:59:28 worker.1 | 2016-01-14T05:59:28.655Z 42480 TID-ov6c4r79k WARN: {"class"=>"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper", "wrapped"=>"DripContentJob", "queue"=>"default", "args"=>[{"job_class"=>"DripContentJob", "job_id"=>"6f8a4e88-32ca-4dc2-a67b-ebf4000f4c5d", "queue_name"=>"default", "arguments"=>[[31, 32], [10], 9], "locale"=>"en"}], "retry"=>true, "jid"=>"9cd3d4c8b1cfe2d050229ae1", "created_at"=>1452751163.652608, "apartment"=>"oki", "enqueued_at"=>1452751163.652664}
21:59:28 worker.1 | 2016-01-14T05:59:28.655Z 42480 TID-ov6c4r79k WARN: ActiveRecord::ConnectionTimeoutError: could not obtain a database connection within 5.000 seconds (waited 5.001 seconds)
21:59:28 worker.1 | 2016-01-14T05:59:28.655Z 42480 TID-ov6c4r79k WARN: /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:189:in `block in wait_poll'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:180:in `loop'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:180:in `wait_poll'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:135:in `block in poll'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `synchronize'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:133:in `poll'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:425:in `acquire_connection'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:349:in `block in checkout'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:348:in `checkout'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:263:in `block in connection'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/rubies/ruby-2.2.3/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:262:in `connection'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract/connection_pool.rb:571:in `retrieve_connection'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_handling.rb:113:in `retrieve_connection'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/activerecord-4.2.5/lib/active_record/connection_handling.rb:87:in `connection'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/apartment-1.0.2/lib/apartment/adapters/postgresql_adapter.rb:73:in `reset'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/apartment-1.0.2/lib/apartment/adapters/postgresql_adapter.rb:39:in `initialize'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/apartment-1.0.2/lib/apartment/adapters/postgresql_adapter.rb:10:in `new'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/apartment-1.0.2/lib/apartment/adapters/postgresql_adapter.rb:10:in `postgresql_adapter'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/apartment-1.0.2/lib/apartment/tenant.rb:48:in `adapter'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/apartment-sidekiq-1.0.0/lib/apartment/sidekiq/middleware/server.rb:4:in `call'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/logging.rb:30:in `with_context'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/middleware/server/logging.rb:7:in `call'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/middleware/chain.rb:132:in `call'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/middleware/chain.rb:132:in `invoke'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/processor.rb:127:in `block in process'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/processor.rb:166:in `stats'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/processor.rb:126:in `process'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/processor.rb:79:in `process_one'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/processor.rb:67:in `run'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/util.rb:16:in `watchdog'
21:59:28 worker.1 | /Users/typeoneerror/.rvm/gems/ruby-2.2.3@doki/gems/sidekiq-4.0.2/lib/sidekiq/util.rb:24:in `block in safe_thread'

[typeoneerror]

Also tracking the issue here: influitive/apartment-sidekiq#11. Based on the fact that rolling back to apartment-sidekiq 0.2.0 fixes the issue, I'm thinking this is probably an issue with how they are inserting the middleware here: https://github.com/influitive/apartment-sidekiq/blob/master/lib/apartment/sidekiq.rb#L24

[mperham]

Since you mentioned this fails on both Sidekiq 3 and 4, I'm going to assume the issue is with apartment-sidekiq and is something they need to deal with.