Bug 1391906

Summary: ConnectionTimeoutError: could not obtain a connection from the pool ... all pooled connections were in use
Product: Red Hat CloudForms Management Engine Reporter: Gellert Kis <gekis>
Component: ApplianceAssignee: Gregg Tanzillo <gtanzill>
Status: CLOSED NOTABUG QA Contact: Dave Johnson <dajohnso>
Severity: high Docs Contact:
Priority: high    
Version: 5.6.0CC: abellott, cpelland, gekis, gtanzill, jhardy, jrafanie, obarenbo
Target Milestone: GAFlags: jrafanie: needinfo? (gekis)
Target Release: 5.7.1   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
cfme 5.6.2.2
Last Closed: 2016-12-16 22:12:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: Bug
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Gellert Kis 2016-11-04 11:06:45 UTC 
Description of problem:

reported error "Error in update_worker_record_at_exit: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use" seems to be a bit misleading as all 10 pool connections appear to be consumed in less than 4 seconds.

[----] E, [2016-11-01T11:38:20.373194 #27652:129ac38] ERROR -- : MIQ(Vmdb::Settings::DatabaseSource#load) ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds);
 all pooled connections were in use
[----] E, [2016-11-01T11:38:20.373522 #27652:129ac38] ERROR -- : MIQ(Vmdb::Settings::DatabaseSource#load) /opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:202:in `block 
in wait_poll'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `loop'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `block in poll'
/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:158:in `synchronize'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `poll'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:709:in `acquire_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:501:in `checkout'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:364:in `connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:875:in `retrieve_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_handling.rb:128:in `retrieve_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_handling.rb:91:in `connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/association.rb:97:in `association_scope'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/association.rb:86:in `scope'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_association.rb:447:in `scope'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/association.rb:261:in `skip_statement_cache?'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_association.rb:458:in `get_records'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_association.rb:473:in `find_target'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_association.rb:412:in `load_target'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/association.rb:53:in `reload'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_proxy.rb:1046:in `reload'
/var/www/miq/vmdb/lib/vmdb/settings/database_source.rb:15:in `load'
/opt/rh/cfme-gemset/bundler/gems/config-23ce4b89d31f/lib/config/options.rb:54:in `block in reload!'
/opt/rh/cfme-gemset/bundler/gems/config-23ce4b89d31f/lib/config/options.rb:53:in `each'
/opt/rh/cfme-gemset/bundler/gems/config-23ce4b89d31f/lib/config/options.rb:53:in `reload!'
/var/www/miq/vmdb/lib/patches/config_patch.rb:3:in `reload!'
/var/www/miq/vmdb/lib/vmdb/settings.rb:26:in `reload!'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:283:in `sync_config'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:278:in `message_sync_config'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:457:in `process_message'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:358:in `block in heartbeat'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:358:in `each'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:358:in `heartbeat'
/var/www/miq/vmdb/gems/manageiq-providers-amazon/app/models/manageiq/providers/amazon/cloud_manager/event_catcher/runner.rb:38:in `block in event_monitor_handle'
/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:382:in `call'
/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:382:in `get_messages'
/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:332:in `block (2 levels) in poll'
/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:331:in `loop'
/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:331:in `block in poll'
/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:330:in `catch'
/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:330:in `poll'
/var/www/miq/vmdb/gems/manageiq-providers-amazon/app/models/manageiq/providers/amazon/cloud_manager/event_catcher/stream.rb:52:in `block in poll'
/var/www/miq/vmdb/app/models/ext_management_system.rb:363:in `with_provider_connection'
/var/www/miq/vmdb/gems/manageiq-providers-amazon/app/models/manageiq/providers/amazon/cloud_manager/event_catcher/stream.rb:44:in `poll'
/var/www/miq/vmdb/gems/manageiq-providers-amazon/app/models/manageiq/providers/amazon/cloud_manager/event_catcher/runner.rb:9:in `monitor_events'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/event_catcher/runner.rb:112:in `block in start_event_monitor'
/opt/rh/cfme-gemset/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `call'
/opt/rh/cfme-gemset/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context'
[----] I, [2016-11-01T11:38:20.373785 #27652:129ac38]  INFO -- : EMS [] as [AKIAIH4OIXOEKGMUYEMA] ID [4253000000021269] PID [27652] GUID [374f3160-a00a-11e6-9292-005056bf407d] Error heartbeating because ActiveRecord::ConnectionTimeo
utError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use


###############################################

[----] E, [2016-11-01T11:38:25.374824 #27652:129ac38] ERROR -- : EMS [] as [AKIAIH4OIXOEKGMUYEMA] ID [4253000000021269] PID [27652] GUID [374f3160-a00a-11e6-9292-005056bf407d] Error in update_worker_record_at_exit: could not obtain 
a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
[----] E, [2016-11-01T11:38:25.375260 #27652:129ac38] ERROR -- : EMS [] as [AKIAIH4OIXOEKGMUYEMA] ID [4253000000021269] PID [27652] GUID [374f3160-a00a-11e6-9292-005056bf407d] Error heartbeating because ActiveRecord::ConnectionTimeo
utError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:202:in `block in wait_poll'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstrac
t/connection_pool.rb:193:in `loop'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/
connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'\n/opt/rh/cfme-gemset/gems
/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `block in poll'\n/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1
/lib/active_record/connection_adapters/abstract/connection_pool.rb:158:in `synchronize'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `poll'\n/opt/rh/cfme-gem
set/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:709:in `acquire_connection'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_poo
l.rb:501:in `checkout'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:364:in `connection'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_
adapters/abstract/connection_pool.rb:875:in `retrieve_connection'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/connection_handling.rb:128:in `retrieve_connection'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/li
b/active_record/connection_handling.rb:91:in `connection'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/association.rb:97:in `association_scope'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/acti
ve_record/associations/association.rb:86:in `scope'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_association.rb:447:in `scope'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_rec
ord/associations/association.rb:261:in `skip_statement_cache?'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_association.rb:458:in `get_records'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0
.1/lib/active_record/associations/collection_association.rb:473:in `find_target'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_association.rb:412:in `load_target'\n/opt/rh/cfme-gemset/gems/
activerecord-5.0.0.1/lib/active_record/associations/association.rb:53:in `reload'\n/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/associations/collection_proxy.rb:1046:in `reload'\n/var/www/miq/vmdb/lib/vmdb/setting
s/database_source.rb:15:in `load'\n/opt/rh/cfme-gemset/bundler/gems/config-23ce4b89d31f/lib/config/options.rb:54:in `block in reload!'\n/opt/rh/cfme-gemset/bundler/gems/config-23ce4b89d31f/lib/config/options.rb:53:in `each'\n/opt/rh
/cfme-gemset/bundler/gems/config-23ce4b89d31f/lib/config/options.rb:53:in `reload!'\n/var/www/miq/vmdb/lib/patches/config_patch.rb:3:in `reload!'\n/var/www/miq/vmdb/lib/vmdb/settings.rb:26:in `reload!'\n/var/www/miq/vmdb/app/models/
miq_worker/runner.rb:283:in `sync_config'\n/var/www/miq/vmdb/app/models/miq_worker/runner.rb:278:in `message_sync_config'\n/var/www/miq/vmdb/app/models/miq_worker/runner.rb:457:in `process_message'\n/var/www/miq/vmdb/app/models/miq_
worker/runner.rb:358:in `block in heartbeat'\n/var/www/miq/vmdb/app/models/miq_worker/runner.rb:358:in `each'\n/var/www/miq/vmdb/app/models/miq_worker/runner.rb:358:in `heartbeat'\n/var/www/miq/vmdb/gems/manageiq-providers-amazon/ap
p/models/manageiq/providers/amazon/cloud_manager/event_catcher/runner.rb:38:in `block in event_monitor_handle'\n/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:382:in `call'\n/opt
/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:382:in `get_messages'\n/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:332:in `blo
ck (2 levels) in poll'\n/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:331:in `loop'\n/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_p
oller.rb:331:in `block in poll'\n/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/sqs/queue_poller.rb:330:in `catch'\n/opt/rh/cfme-gemset/gems/aws-sdk-resources-2.2.37/lib/aws-sdk-resources/services/s
qs/queue_poller.rb:330:in `poll'\n/var/www/miq/vmdb/gems/manageiq-providers-amazon/app/models/manageiq/providers/amazon/cloud_manager/event_catcher/stream.rb:52:in `block in poll'\n/var/www/miq/vmdb/app/models/ext_management_system.
rb:363:in `with_provider_connection'\n/var/www/miq/vmdb/gems/manageiq-providers-amazon/app/models/manageiq/providers/amazon/cloud_manager/event_catcher/stream.rb:44:in `poll'\n/var/www/miq/vmdb/gems/manageiq-providers-amazon/app/mod
els/manageiq/providers/amazon/cloud_manager/event_catcher/runner.rb:9:in `monitor_events'\n/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/event_catcher/runner.rb:112:in `block in start_event_monitor'\n/opt/rh/cfme-gems
et/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `call'\n/opt/rh/cfme-gemset/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context' Worker exiting.

###################################################

[----] I, [2016-11-01T11:39:00.670724 #5771:df7988]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] ....
[----] I, [2016-11-01T11:39:02.140827 #5771:df7988]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager::EventCatcher::Runner#start_event_monitor) EMS [] as [AKIAIH4OIXOEKGMUYEMA] Validating Connection/Credentials [----] I, [2016-11-01T11:39:02.141027 #5771:df7988]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] [----] I, [2016-11-01T11:39:02.267350 #5771:df7988]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager::EventCatcher::Runner#start_event_monitor) EMS [] as [AKIAIH4OIXOEKGMUYEMA] Starting Event Monitor Thread [----] I, [2016-11-01T11:39:02.271905 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] [----] I, [2016-11-01T11:39:02.314725 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] [----] I, [2016-11-01T11:39:02.511029 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] [----] I, [2016-11-01T11:39:02.747616 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] ...
[----] I, [2016-11-01T11:39:02.922245 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] [----] I, [2016-11-01T11:39:02.983726 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] [----] I, [2016-11-01T11:39:03.031622 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI] [----] I, [2016-11-01T11:39:03.091173 #5771:11aefe0]  INFO -- : MIQ(ManageIQ::Providers::Amazon::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Amazon::CloudManager: [ACI]

//////////

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:
Comment 2 Joe Rafaniello 2016-12-16 21:59:48 UTC 
Hi Gellert,

The reported error is saying that Rails waited 5 seconds for a free connection from the database connection pool to become available before failing.  It's a timeout for how long it should wait for a connection.

It's not checking to see how quickly the connection pool becomes fully leased out.

Is there something else needed for this bug?
Comment 3 Joe Rafaniello 2016-12-16 22:12:54 UTC 
Closing, this error message comes from Rails and describes the connection timeout.

If this was closed in error, please respond and we can reopen, thanks!
Comment 4 Gellert Kis 2017-01-02 09:58:37 UTC 
Is there a way to setup a connection timeout for Rails waiting for a database connection pool?
Comment 5 Joe Rafaniello 2017-01-03 15:54:10 UTC 
You can configure the connection timeout by setting a wait_timeout in config/database.yml:

https://github.com/ManageIQ/manageiq/blob/b27acf537a9b3c1249f6bcb76821db2d69ed87b2/config/database.pg.yml#L19

The default is 5 seconds.
Comment 7 Joe Rafaniello 2018-03-19 18:43:19 UTC 
Hi Gellert, config/database.yml is a Rails configuration file that is needed before we can talk to the database so we can't really "configure" it in the UI.  You need to visit each appliance to configure the database.yml.  We try to limit and simplify it in initial setup in the appliance_console.