Currently Katello nightly is breaking due to the MonitorEventQueue not processing properly which is affecting errata applicability calculations. The error messages I am seeing in the logs are related to database connection issues. I have not dug into this other than some stack overflow posts that seem to indicate Rails 5 and concurrency has issues with database connections. If @iNecas or @aruzicka or anyone else with some knowledge in this area could take a look. I have attempted to up the pool numbers to 20 with the same error output. If I restart dynflowd, the event queue is processed, then enters an error state and processes no more. The CandlepinEventListener shows some of the same errors as well as some of the notification background processing for the UI. Here are some errors I see, these come from:
vagrant up centos7-katello-bats-ci
2018-03-09T03:30:49 [background] [E] could not obtain a connection from the pool within 5.000 seconds (waited 5.003 seconds); all pooled connections were in use (ActiveRecord::ConnectionTimeoutError)
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:202:in `block in wait_poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `loop'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `block in poll'
| /opt/rh/rh-ruby24/root/usr/share/ruby/monitor.rb:214:in `mon_synchronize'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:158:in `synchronize'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:148:in `poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:747:in `acquire_connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:500:in `checkout'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:374:in `connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:931:in `retrieve_connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_handling.rb:116:in `retrieve_connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_handling.rb:88:in `connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/associations/join_dependency.rb:96:in `initialize'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation/query_methods.rb:1016:in `new'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation/query_methods.rb:1016:in `build_join_query'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation/query_methods.rb:1003:in `build_joins'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation/query_methods.rb:942:in `build_arel'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation/query_methods.rb:918:in `arel'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation.rb:667:in `exec_queries'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation.rb:546:in `load'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation.rb:255:in `records'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/relation/delegation.rb:39:in `each'
| /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/services/katello/ui_notifications/pulp/proxy_disk_space.rb:7:in `deliver!'
| /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/jobs/create_pulp_disk_space_notifications.rb:7:in `perform'
2018-03-09T03:30:54 [dynflow] [E] could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
2018-03-09T03:30:54 [dynflow] [E] /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:202:in `block in wait_poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `loop'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'
2018-03-09T03:30:54 [dynflow] [W] Error on on_execution_plan_save event
| ActiveRecord::ConnectionNotEstablished: No connection pool with 'primary' found.
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:930:in `retrieve_connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_handling.rb:116:in `retrieve_connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_handling.rb:88:in `connection'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/transactions.rb:210:in `transaction'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/transactions.rb:381:in `with_transaction_returning_status'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/transactions.rb:313:in `save!'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/suppressor.rb:46:in `save!'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/app/models/foreman_tasks/task/dynflow_task.rb:24:in `update_from_dynflow'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/lib/foreman_tasks/dynflow/persistence.rb:43:in `on_execution_plan_save'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/lib/foreman_tasks/dynflow/persistence.rb:12:in `block in save_execution_plan'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/lib/foreman_tasks/dynflow/persistence.rb:10:in `tap'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/lib/foreman_tasks/dynflow/persistence.rb:10:in `save_execution_plan'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/persistence.rb:73:in `save_execution_plan'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/execution_plan.rb:423:in `save'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/execution_plan.rb:132:in `update_state'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/director/execution_plan_manager.rb:101:in `finish'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/director/execution_plan_manager.rb:74:in `compute_next_from_step'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/director/execution_plan_manager.rb:42:in `what_is_next'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/director.rb:107:in `work_finished'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/executors/parallel/core.rb:35:in `work_finished'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/actor.rb:6:in `on_message'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/executors/parallel/core.rb:67:in `on_message'
| /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/context.rb:46:in `on_envelope'
2018-03-09T03:30:54 [background] [E] ActiveRecord::ConnectionNotEstablished (ActiveRecord::ConnectionNotEstablished)
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/connection_handling.rb:112:in `connection_pool'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.4/lib/active_record/query_cache.rb:27:in `run'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/execution_wrapper.rb:25:in `before'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:413:in `block in make_lambda'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:197:in `block (2 levels) in halting'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:601:in `block (2 levels) in default_terminator'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:600:in `catch'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:600:in `block in default_terminator'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:198:in `block in halting'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:507:in `block in invoke_before'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:507:in `each'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:507:in `invoke_before'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:130:in `run_callbacks'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/execution_wrapper.rb:108:in `run!'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/execution_wrapper.rb:70:in `block in run!'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/execution_wrapper.rb:67:in `tap'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/execution_wrapper.rb:67:in `run!'
| /opt/rh/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.4/lib/active_support/execution_wrapper.rb:83:in `wrap'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:22:in `call'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:26:in `pass'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware.rb:18:in `pass'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/action/progress.rb:30:in `with_progress_calculation'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/action/progress.rb:16:in `run'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:22:in `call'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:26:in `pass'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware.rb:18:in `pass'
| /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/keep_locale.rb:11:in `block in run'
| /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/keep_locale.rb:22:in `with_locale'
| /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/keep_locale.rb:11:in `run'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:22:in `call'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:26:in `pass'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware.rb:18:in `pass'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/app/lib/actions/middleware/keep_current_user.rb:28:in `block in run'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/app/lib/actions/middleware/keep_current_user.rb:51:in `restore_curent_user'
| /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.12.0/app/lib/actions/middleware/keep_current_user.rb:28:in `run'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:22:in `call'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware/stack.rb:26:in `pass'
| /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.36/lib/dynflow/middleware.rb:18:in `pass'