{"action":"created","issue":{"url":"https://api.github.com/repos/mperham/sidekiq/issues/3254","repository_url":"https://api.github.com/repos/mperham/sidekiq","labels_url":"https://api.github.com/repos/mperham/sidekiq/issues/3254/labels{/name}","comments_url":"https://api.github.com/repos/mperham/sidekiq/issues/3254/comments","events_url":"https://api.github.com/repos/mperham/sidekiq/issues/3254/events","html_url":"https://github.com/mperham/sidekiq/issues/3254","id":191175139,"number":3254,"title":"ActiveRecord times out even when not used in a job if the connection pool is empty","user":{"login":"kreynolds","id":324744,"avatar_url":"https://avatars.githubusercontent.com/u/324744?v=3","gravatar_id":"","url":"https://api.github.com/users/kreynolds","html_url":"https://github.com/kreynolds","followers_url":"https://api.github.com/users/kreynolds/followers","following_url":"https://api.github.com/users/kreynolds/following{/other_user}","gists_url":"https://api.github.com/users/kreynolds/gists{/gist_id}","starred_url":"https://api.github.com/users/kreynolds/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kreynolds/subscriptions","organizations_url":"https://api.github.com/users/kreynolds/orgs","repos_url":"https://api.github.com/users/kreynolds/repos","events_url":"https://api.github.com/users/kreynolds/events{/privacy}","received_events_url":"https://api.github.com/users/kreynolds/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2016-11-23T02:26:51Z","updated_at":"2016-11-23T03:01:34Z","closed_at":null,"body":"Ruby version: 2.3.1\r\nSidekiq / Pro / Enterprise version(s): 4.2.6 / 3.4.0 / 1.4.0\r\n\r\nIf relevant, please include your initializer and any error message with the full backtrace.\r\nI've triple checked that there are no AR calls in this job and while I could be missing something still, it looks like it tries to get a connection even if it doesn't need one according to the backtrace.\r\n\r\n```\r\n2016-11-23T02:22:34.607Z 27199 TID-7ykv36o WARN: ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.145 seconds); all pooled connections were in use\r\n```\r\n\r\n```\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `loop'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `block in poll'\r\n/home/rails/.rbenv/versions/2.3.1/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:158:in `synchronize'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `poll'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:709:in `acquire_connection'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:501:in `checkout'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:364:in `connection'\r\nactiverecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:875:in `retrieve_connection'\r\nactiverecord-5.0.0.1/lib/active_record/connection_handling.rb:128:in `retrieve_connection'\r\nactiverecord-5.0.0.1/lib/active_record/connection_handling.rb:91:in `connection'\r\nactiverecord-5.0.0.1/lib/active_record/query_cache.rb:27:in `run'\r\nactivesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:39:in `block in register_hook'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `instance_exec'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `block in make_lambda'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:547:in `block (2 levels) in default_terminator'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `catch'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `block in default_terminator'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:170:in `block in halting'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `block in call'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `each'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `call'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_run_callbacks'\r\nactivesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'\r\nactivesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:99:in `run!'\r\nactivesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:61:in `block in run!'\r\nactivesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `tap'\r\nactivesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `run!'\r\nactivesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:74:in `wrap'\r\nsidekiq-4.2.6/lib/sidekiq/rails.rb:84:in `call'\r\nsidekiq-4.2.6/lib/sidekiq/processor.rb:133:in `block (3 levels) in process'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'\r\nsidekiq-pro-3.4.0/lib/sidekiq/batch/middleware.rb:33:in `call'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\r\nsidekiq-ent-1.4.0/lib/sidekiq-ent/unique.rb:124:in `call'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\r\nsidekiq-ent-1.4.0/lib/sidekiq-ent/limiter/middleware.rb:38:in `call'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'\r\nsidekiq-4.2.6/lib/sidekiq/logging.rb:32:in `with_context'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/server/logging.rb:7:in `call'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\r\nsidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:133:in `invoke'\r\nsidekiq-4.2.6/lib/sidekiq/processor.rb:132:in `block (2 levels) in process'\r\nsidekiq-4.2.6/lib/sidekiq/processor.rb:174:in `stats'\r\nsidekiq-4.2.6/lib/sidekiq/processor.rb:131:in `block in process'\r\nsidekiq-4.2.6/lib/sidekiq.rb:35:in `block in <module:Sidekiq>'\r\nsidekiq-4.2.6/lib/sidekiq/processor.rb:126:in `process'\r\nsidekiq-4.2.6/lib/sidekiq/processor.rb:82:in `process_one'\r\nsidekiq-4.2.6/lib/sidekiq/processor.rb:70:in `run'\r\nsidekiq-4.2.6/lib/sidekiq/util.rb:17:in `watchdog'\r\nsidekiq-4.2.6/lib/sidekiq/util.rb:25:in `block in safe_thread'\r\n```"},"comment":{"url":"https://api.github.com/repos/mperham/sidekiq/issues/comments/262425196","html_url":"https://github.com/mperham/sidekiq/issues/3254#issuecomment-262425196","issue_url":"https://api.github.com/repos/mperham/sidekiq/issues/3254","id":262425196,"user":{"login":"mperham","id":2911,"avatar_url":"https://avatars.githubusercontent.com/u/2911?v=3","gravatar_id":"","url":"https://api.github.com/users/mperham","html_url":"https://github.com/mperham","followers_url":"https://api.github.com/users/mperham/followers","following_url":"https://api.github.com/users/mperham/following{/other_user}","gists_url":"https://api.github.com/users/mperham/gists{/gist_id}","starred_url":"https://api.github.com/users/mperham/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mperham/subscriptions","organizations_url":"https://api.github.com/users/mperham/orgs","repos_url":"https://api.github.com/users/mperham/repos","events_url":"https://api.github.com/users/mperham/events{/privacy}","received_events_url":"https://api.github.com/users/mperham/received_events","type":"User","site_admin":false},"created_at":"2016-11-23T03:01:34Z","updated_at":"2016-11-23T03:01:34Z","body":"This looks like a Rails 5 issue. \n\n> On Nov 22, 2016, at 6:26 PM, Kelley Reynolds <notifications@github.com> wrote:\n> \n> Ruby version: 2.3.1\n> Sidekiq / Pro / Enterprise version(s): 4.2.6 / 3.4.0 / 1.4.0\n> \n> If relevant, please include your initializer and any error message with the full backtrace.\n> I've triple checked that there are no AR calls in this job and while I could be missing something still, it looks like it tries to get a connection even if it doesn't need one according to the backtrace.\n> \n> 2016-11-23T02:22:34.607Z 27199 TID-7ykv36o WARN: ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.145 seconds); all pooled connections were in use\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `loop'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `block in poll'\n> /home/rails/.rbenv/versions/2.3.1/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:158:in `synchronize'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `poll'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:709:in `acquire_connection'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:501:in `checkout'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:364:in `connection'\n> activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:875:in `retrieve_connection'\n> activerecord-5.0.0.1/lib/active_record/connection_handling.rb:128:in `retrieve_connection'\n> activerecord-5.0.0.1/lib/active_record/connection_handling.rb:91:in `connection'\n> activerecord-5.0.0.1/lib/active_record/query_cache.rb:27:in `run'\n> activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:39:in `block in register_hook'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `instance_exec'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:396:in `block in make_lambda'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:547:in `block (2 levels) in default_terminator'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `catch'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:546:in `block in default_terminator'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:170:in `block in halting'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `block in call'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `each'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `call'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_run_callbacks'\n> activesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'\n> activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:99:in `run!'\n> activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:61:in `block in run!'\n> activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `tap'\n> activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:58:in `run!'\n> activesupport-5.0.0.1/lib/active_support/execution_wrapper.rb:74:in `wrap'\n> sidekiq-4.2.6/lib/sidekiq/rails.rb:84:in `call'\n> sidekiq-4.2.6/lib/sidekiq/processor.rb:133:in `block (3 levels) in process'\n> sidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'\n> sidekiq-pro-3.4.0/lib/sidekiq/batch/middleware.rb:33:in `call'\n> sidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n> sidekiq-ent-1.4.0/lib/sidekiq-ent/unique.rb:124:in `call'\n> sidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n> sidekiq-ent-1.4.0/lib/sidekiq-ent/limiter/middleware.rb:38:in `call'\n> sidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n> sidekiq-4.2.6/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'\n> sidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n> sidekiq-4.2.6/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'\n> sidekiq-4.2.6/lib/sidekiq/logging.rb:32:in `with_context'\n> sidekiq-4.2.6/lib/sidekiq/middleware/server/logging.rb:7:in `call'\n> sidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n> sidekiq-4.2.6/lib/sidekiq/middleware/chain.rb:133:in `invoke'\n> sidekiq-4.2.6/lib/sidekiq/processor.rb:132:in `block (2 levels) in process'\n> sidekiq-4.2.6/lib/sidekiq/processor.rb:174:in `stats'\n> sidekiq-4.2.6/lib/sidekiq/processor.rb:131:in `block in process'\n> sidekiq-4.2.6/lib/sidekiq.rb:35:in `block in <module:Sidekiq>'\n> sidekiq-4.2.6/lib/sidekiq/processor.rb:126:in `process'\n> sidekiq-4.2.6/lib/sidekiq/processor.rb:82:in `process_one'\n> sidekiq-4.2.6/lib/sidekiq/processor.rb:70:in `run'\n> sidekiq-4.2.6/lib/sidekiq/util.rb:17:in `watchdog'\n> sidekiq-4.2.6/lib/sidekiq/util.rb:25:in `block in safe_thread'\n> —\n> You are receiving this because you are subscribed to this thread.\n> Reply to this email directly, view it on GitHub, or mute the thread.\n> \n"}}
{"actor":{"display_login":"mperham"}}