[SOLVED] Lots of ActiveRecord::ConnectionTimeoutError in evm.log for Vmware::InfraManager::RefreshWorker

Hi, I noticed that in one of our vcenters linked to ManageIQ automate jobs where stuck in the Validate VM step during provisioning
As far I understand that’s because ManageIQ cannot refresh the vCenter inventory and “see” the new VM

In the logs I have lots of the following messages:
[----] E, [2021-04-29T03:50:09.596730 #2965706:2aafe89d714c] ERROR – : [ActiveRecord::ConnectionTimeoutError]: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use Method:[block (2 levels) in class:LogProxy]
[----] E, [2021-04-29T03:50:09.597156 #2965706:2aafe89d714c] ERROR – : /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:201:in block in wait_poll' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in loop’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in wait_poll' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:151:in internal_poll’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:277:in internal_poll' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in block in poll’
/usr/share/ruby/monitor.rb:230:in mon_synchronize' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:155:in synchronize’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in poll' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:818:in acquire_connection’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:538:in checkout' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:382:in connection’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:1033:in retrieve_connection' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_handling.rb:118:in retrieve_connection’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/connection_handling.rb:90:in connection' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/relation/delegation.rb:76:in connection’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/relation.rb:530:in alias_tracker' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/association_scope.rb:26:in scope’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/association_scope.rb:7:in scope' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/association.rb:90:in association_scope’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/association.rb:79:in scope' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/collection_association.rb:287:in scope’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/collection_association.rb:305:in find_target' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/collection_association.rb:272:in load_target’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/collection_proxy.rb:46:in load_target' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/associations/collection_proxy.rb:1004:in records’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/relation/delegation.rb:71:in each' /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/relation/query_methods.rb:226:in select’
/opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/relation/query_methods.rb:226:in select' /var/www/miq/vmdb/app/models/mixins/authentication_mixin.rb:85:in authentication_userid_passwords’
/var/www/miq/vmdb/app/models/mixins/authentication_mixin.rb:491:in available_authentications' /var/www/miq/vmdb/app/models/mixins/authentication_mixin.rb:257:in authentication_type’
/var/www/miq/vmdb/app/models/mixins/authentication_mixin.rb:479:in authentication_best_fit' /var/www/miq/vmdb/app/models/mixins/authentication_mixin.rb:157:in auth_user_pwd’
/opt/manageiq/manageiq-gemset/bundler/gems/manageiq-providers-vmware-eb218a96aad1/app/models/manageiq/providers/vmware/infra_manager/inventory/collector.rb:137:in vim_connect' /opt/manageiq/manageiq-gemset/bundler/gems/manageiq-providers-vmware-eb218a96aad1/app/models/manageiq/providers/vmware/infra_manager/inventory/collector.rb:61:in vim_collector’
/opt/manageiq/manageiq-gemset/bundler/gems/manageiq-providers-vmware-eb218a96aad1/app/models/manageiq/providers/vmware/infra_manager/inventory/collector.rb:55:in `block in vim_collector_thread’
[----] E, [2021-04-29T03:50:12.348586 #3552608:2aced87f3b14] ERROR – : MIQ(ManageIQ::Providers::Vmware::InfraManager::Inventory::Collector#vim_collector) EMS: [vCenter Apra Prod], id: [2] Refresh failed
[----] E, [2021-04-29T03:50:12.348930 #3552608:2aced87f3b14] ERROR – : [ActiveRecord::ConnectionTimeoutError]: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use Method:[block (2 levels) in class:LogProxy]

The only way to get it to work is kill the RefreshWorkers and wait for them to respawn

I’m using kasparov-1 and vCenter Server is 7.0 update 1

Thanks

I missed this: Cannot refresh the data from the vCenter

I’m trying the suggested patch and report the results

Ok, issue solved :slight_smile:

1 Like