Hide Forgot
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:
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?
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!
Is there a way to setup a connection timeout for Rails waiting for a database connection pool?
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.
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.