Openstack Provisioning "Timout" or "Rollback"

Trying to get Openstack Provisioning working in my environment. RHEL OS seems fine as it has pretty small images which spin up quickly, However Windows being Windows, our images are fairly large. This translates to extra time to “create” in openstack, especially when we use dedicated boot volumes. I feel like i’m hitting some kind of foreman timeout when i build. It seems like when i build it intermittently completes, however if after ~5 minutes its still “spawning” in openstack, foreman will “error” and roll the whole thing back.

Log messages for reference:
API Call to build:

2018-03-30 15:59:38 d0d83970 [app] [I] Started POST "/hosts" for 10.31.8.101 at 2018-03-30 15:59:38 -0400
2018-03-30 15:59:38 d0d83970 [app] [I] Processing by HostsController#create as */*
2018-03-30 15:59:38 d0d83970 [app] [I]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"uCzBdN0UbpPUXaPDu9ObmLhbUCyKWRqe0qmAR8Ci8/fugz/Lm7RX/gYvoCLWGe7CSfoDKYzlLl4R7VOzGYRC+A==", "host"=>{"name"=>"phoenixnpw1", "organization_id"=>"6", "location_id"=>"151", "hostgroup_id"=>"11", "compute_resource_id"=>"302", "environment_id"=>"302", "ansible_role_ids"=>[""], "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"", "identifier"=>"", "name"=>"phoenixnpw1", "domain_id"=>"106", "subnet_id"=>"2079", "ip"=>"", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>""}}, "compute_attributes"=>{"flavor_ref"=>"e095d243-fca2-41f6-b63c-bc016d91752c", "availability_zone"=>"nova", "tenant_id"=>"b7389a81259c43b490bcd0684d810917", "security_groups"=>"default", "nics"=>["", "9c8ac251-d3e9-40bb-a12a-026db61a5310"], "network"=>"", "boot_from_volume"=>"true", "size_gb"=>"150", "scheduler_hint_filter"=>"", "image_ref"=>"ab6fc018-617b-44b4-8a2c-877bec5b7d4a"}, "architecture_id"=>"1", "operatingsystem_id"=>"391", "provision_method"=>"image", "build"=>"1", "medium_id"=>"", "ptable_id"=>"", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "root_pass"=>"[FILTERED]", "host_parameters_attributes"=>{"1522439449792"=>{"name"=>"payx_builder", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}, "1522439460128"=>{"name"=>"payx_environment", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}, "1522439480538"=>{"name"=>"payx_hostgroup", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}, "1522439514658"=>{"name"=>"payx_nodestatus", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}, "1522439590410"=>{"name"=>"payx_prod", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}}, "is_owned_by"=>"141-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "capabilities"=>"image key_pair", "provider"=>"Openstack", "bare_metal_capabilities"=>"build"}
2018-03-30 15:59:38 d0d83970 [app] [I] Current user: jlang1 (administrator)
2018-03-30 15:59:39 d0d83970 [app] [I] Rendering UserData template for phoenixnpw1.is.payxdev.com
2018-03-30 15:59:39 d0d83970 [templates] [I] Rendering template 'Unnamed'

Seems to refresh/check once per second the “task” status?

2018-03-30 15:59:41 73ee7b81 [app] [I] Started GET "/tasks/1bc1089a-ca07-41c2-b69c-4590c66207d6" for 10.31.8.101 at 2018-03-30 15:59:41 -0400
2018-03-30 15:59:41 73ee7b81 [app] [I] Processing by TasksController#show as */*
2018-03-30 15:59:41 73ee7b81 [app] [I]   Parameters: {"id"=>"1bc1089a-ca07-41c2-b69c-4590c66207d6"}
2018-03-30 15:59:41 73ee7b81 [app] [I] Current user: jlang1 (administrator)
2018-03-30 15:59:41 73ee7b81 [app] [I]   Rendered tasks/_list.html.erb (0.4ms)
2018-03-30 15:59:41 73ee7b81 [app] [I] Completed 200 OK in 19ms (Views: 1.1ms | ActiveRecord: 7.0ms)
2018-03-30 15:59:41 911f6f87 [app] [I] Started GET "/notification_recipients" for 10.31.8.101 at 2018-03-30 15:59:41 -0400
2018-03-30 15:59:41 911f6f87 [app] [I] Processing by NotificationRecipientsController#index as JSON
2018-03-30 15:59:41 911f6f87 [app] [I] Current user: jlang1 (administrator)
2018-03-30 15:59:41 911f6f87 [app] [I] Completed 200 OK in 9ms (Views: 0.3ms | ActiveRecord: 2.8ms)
2018-03-30 15:59:43 545d1854 [app] [I] Started GET "/tasks/1bc1089a-ca07-41c2-b69c-4590c66207d6" for 10.31.8.101 at 2018-03-30 15:59:43 -0400
2018-03-30 15:59:43 545d1854 [app] [I] Processing by TasksController#show as */*
2018-03-30 15:59:43 545d1854 [app] [I]   Parameters: {"id"=>"1bc1089a-ca07-41c2-b69c-4590c66207d6"}
2018-03-30 15:59:43 545d1854 [app] [I] Current user: jlang1 (administrator)
2018-03-30 15:59:43 545d1854 [app] [I]   Rendered tasks/_list.html.erb (0.4ms)
2018-03-30 15:59:43 545d1854 [app] [I] Completed 200 OK in 21ms (Views: 1.0ms | ActiveRecord: 10.5ms)
2018-03-30 15:59:44 e841824f [app] [I] Started GET "/tasks/1bc1089a-ca07-41c2-b69c-4590c66207d6" for 10.31.8.101 at 2018-03-30 15:59:44 -0400
2018-03-30 15:59:44 e841824f [app] [I] Processing by TasksController#show as */*
2018-03-30 15:59:44 e841824f [app] [I]   Parameters: {"id"=>"1bc1089a-ca07-41c2-b69c-4590c66207d6"}
2018-03-30 15:59:44 e841824f [app] [I] Current user: jlang1 (administrator)
2018-03-30 15:59:44 e841824f [app] [I]   Rendered tasks/_list.html.erb (0.4ms)
2018-03-30 15:59:44 e841824f [app] [I] Completed 200 OK in 19ms (Views: 1.0ms | ActiveRecord: 9.1ms)

Finally - after around 5 minutes (3-4 minutes are spent creating my boot volume in openstack due to its size) and a minute or so “spawning” and it will error in foreman, roll back, and delete from openstack.

2018-03-30 16:05:27 d0d83970 [app] [I] Delete the autosign entry for phoenixnpw1.is.payxdev.com
2018-03-30 16:05:27 d0d83970 [app] [I] Processed 3 tasks from queue 'Host::Managed Main', completed 0/4
2018-03-30 16:05:27 d0d83970 [app] [E] Task 'Render user data template for phoenixnpw1.is.payxdev.com' *rollbacked*
2018-03-30 16:05:27 d0d83970 [app] [E] Task 'Set up compute instance phoenixnpw1.is.payxdev.com' *rollbacked*
2018-03-30 16:05:27 d0d83970 [app] [E] Task 'Acquire IP addresses for phoenixnpw1.is.payxdev.com' *rollbacked*
2018-03-30 16:05:27 d0d83970 [app] [E] Task 'Query instance details for phoenixnpw1.is.payxdev.com' *failed*
2018-03-30 16:05:27 d0d83970 [app] [W] Action failed
 | Mysql2::Error: MySQL client is not connected
 | /opt/theforeman/tfm/root/usr/share/gems/gems/mysql2-0.4.5/lib/mysql2/client.rb:120:in `_query'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/mysql2-0.4.5/lib/mysql2/client.rb:120:in `block in query'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/mysql2-0.4.5/lib/mysql2/client.rb:119:in `handle_interrupt'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/mysql2-0.4.5/lib/mysql2/client.rb:119:in `query'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:305:in `block in execute'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract_adapter.rb:472:in `block in log'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract_adapter.rb:466:in `log'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:305:in `execute'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/mysql2_adapter.rb:231:in `execute'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:334:in `exec_rollback_db_transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:266:in `rollback_db_transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/query_cache.rb:14:in `rollback_db_transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/transaction.rb:145:in `rollback'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/transaction.rb:179:in `rollback_transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/transaction.rb:186:in `rescue in within_new_transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/transaction.rb:201:in `within_new_transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:348:in `with_transaction_returning_status'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:286:in `block in save'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:301:in `rollback_active_record_state!'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:285:in `save'
 | /usr/share/foreman/app/models/concerns/foreman/sti.rb:29:in `save_with_type'
 | /usr/share/foreman/app/controllers/hosts_controller.rb:106:in `create'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/base.rb:198:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/rendering.rb:10:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:117:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:117:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.4.1/lib/audited/sweeper.rb:14:in `around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:455:in `public_send'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:455:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/callbacks.rb:19:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/rescue.rb:29:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/notifications.rb:164:in `block in instrument'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/notifications.rb:164:in `instrument'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/base.rb:137:in `process'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionview-4.2.5.1/lib/action_view/rendering.rb:30:in `process'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal.rb:196:in `dispatch'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal.rb:237:in `block in action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:74:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:43:in `serve'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/journey/router.rb:43:in `block in serve'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/journey/router.rb:30:in `each'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/journey/router.rb:30:in `serve'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:815:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.4/lib/apipie/static_dispatcher.rb:65:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.4/lib/apipie/extractor/recorder.rb:136:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/static.rb:116:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/static.rb:116:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/static.rb:116:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/static.rb:116:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.4/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/etag.rb:24:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/conditionalget.rb:38:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/head.rb:13:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
 | /usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/flash.rb:260:in `call'
 | /usr/share/foreman/lib/middleware/session_safe_logging.rb:17:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:225:in `context'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:220:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/cookies.rb:560:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/query_cache.rb:36:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/rack/logger.rb:38:in `call_app'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/rack/logger.rb:22:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/sprockets-rails-3.2.0/lib/sprockets/rails/quiet_assets.rb:13:in `call'
 | /usr/share/foreman/lib/middleware/tagged_logging.rb:18:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/request_id.rb:21:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/methodoverride.rb:22:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/runtime.rb:18:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/static.rb:116:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/sendfile.rb:113:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-3.4.1/lib/secure_headers/middleware.rb:12:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/engine.rb:518:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/application.rb:165:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/railtie.rb:194:in `public_send'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/railtie.rb:194:in `method_missing'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:66:in `block in call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `each'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `call'
 | /usr/share/passenger/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
 | /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
 | /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
 | /usr/share/passenger/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
2018-03-30 16:05:27 d0d83970 [app] [I]   Rendered common/500.html.erb (9.5ms)
2018-03-30 16:05:27 d0d83970 [app] [I] Completed 500 Internal Server Error in 348299ms (Views: 13.4ms | ActiveRecord: 201.9ms)
2018-03-30 16:05:27 d0d83970 [app] [F]
 | ActiveRecord::StatementInvalid (Mysql2::Error: MySQL client is not connected: BEGIN):
 |   lib/middleware/tagged_logging.rb:18:in `call'
 |
 |

The error stack is saying my foreman mysql database “went away” - but i really don’t think it did? We have no other errors anywhere on any other servers. I have mysql workbench open - and its connected. And i have many other clients doing runs and processing reports no problem. Additionally I can reproduce this consistently - the same process above can be triggered anytime an Openstack build doesn’t complete in ~5 minutes.

Am I on the right track that this appears to be a 5 minute (300 second) timeout? Is there a way to bump it up? I’m not sure if it would be an Openshift compute resource timeout, a general “tasks” timeout, a foreman global timeout, or even a database query timeout (though I see no query running for any length of time to indicate its timing out). I did check the foreman admin settings and didn’t see any timeouts that looked like they applied here…

Thanks to anyone with any insight - even if its “your barking up the wrong tree”

So - i did find this bugfix that went out in 1.16 from @Marek_Hulan and Martin Ducar : Feature #19459: Add VM boot failure faster feedback loop for openstack - Foreman

Though the PR add’s in faster feedback by polling openstack for status/failures, it does speak also about the generic Orchestration Task “300 second timeout” which i think I’ hitting.
I browsed the code in the PR above, as well as some related classes, but can’t seem to track down where/how this 300 second timeout is “set”.

Based off of the above PR’s explanation - im pretty im simply hitting the 300 second timeout for Orchestration Tasks. Would anyone know where this is set, or how to increase it? I’m going to keep going through the code to try and find it as well.

Thanks in advance!

~Jason Lang

This is the timeout you are looking for:

Feel free to create Feature ticket, it’s an easy change to add another setting value for this.