Failed to launch script Couldn't find Host::Managed with id and error (ActiveRecord::AssociationTypeMismatch): Host::Managed(#13260) expected, got #<Host::Base

Support
,
1

Recently upgraded about 8 Foreman instances from 3.7 to 3.13, EL8 to EL9, and Postgres 15 to Postgres 17.

As a result, when creating more than 1 host at a time through the API, one host will work fine, and the rest will have the error:

{"errors":{"base":["Failed to launch script on empty-test-box: Couldn't find Host::Managed with 'id'=2979 [WHERE \"hosts\".\"type\" = $1]"]}}

And in the DB record the type is not set, so when this host, that does actually successfully provision, and does show up in the Foreman Postgres DB, runs puppet and tries to upload it’s facts, one sees the error:

 (ActiveRecord::AssociationTypeMismatch): Host::Managed(#13260) expected, got #<Host::Base

And the host doesn’t show up in the UI, though it’s perfectly content to be hanging out in AWS doing it’s thing.

I can set the type to Host::Managed and then puppet runs show up reporting and the host shows up in the UI (which then lets one control it’s lifecycle or even decommission it)

If I build 1 box at a time, it works every time. This only seems to happen when submitting a build for more than 1 at a time through the API call when making AWS hosts. Making Libvirt hosts don’t seem to be impacted with how many hosts I try to make.

2

Should mention the reason we submit multiple builds in parallel, is that one must wait for the EC2 host to spin up, and for foreman to connect to it via SSH to push down the provision script, before the build api call returns, which can take up to 5 minutes. So waiting 5 minutes for 5 hosts to get built, vs 25 minutes makes it a bit quicker to spin up large fleets of boxes. I’ve temproarily set our API calls to have a pool of 1 so that we stop getting errors on the builds, and updated the DBs in all the regions to have the type of Host::Managed on the ones that are missing that just as a temporary bandaid.

3

Example of the logs when the API call comes in to build out 4 hosts:

2025-01-22T20:08:11 [I|app|016f2d41] Started POST "/api/v2/hosts" for xxx at 2025-01-22 20:08:11 +0000
2025-01-22T20:08:11 [I|app|016f2d41] Processing by Api::V2::HostsController#create as JSON
2025-01-22T20:08:11 [I|app|016f2d41]   Parameters: {"host"=>{"managed"=>"true", "ip"=>nil, "compute_resource_id"=>1, "compute_profile_id"=>57, "subnet_id"=>nil, "domain_name"=>"yul1.qprod.net", "domain_id"=>1, "hostgroup_id"=>340, "interfaces_attributes"=>nil, "name"=>"empty-test-box2-app", "build"=>"1", "enabled"=>"1", "location_id"=>3, "organization_id"=>1, "host_parameters_attributes"=>{"0"=>{"name"=>"t3_m4", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "1"=>{"name"=>"aws_access_key_id", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "2"=>{"name"=>"aws_secret_access_key", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "3"=>{"name"=>"facts", "value"=>"[FILTERED]", "parameter_type"=>"hash"}, "4"=>{"name"=>"subnet", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "5"=>{"name"=>"disk_size", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "6"=>{"name"=>"disk_iops", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "7"=>{"name"=>"disk_throughput", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "8"=>{"name"=>"logical_volumes", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "9"=>{"name"=>"swap", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "10"=>{"name"=>"/mnt/data1", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "11"=>{"name"=>"/var/lib/docker", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "12"=>{"name"=>"/var/log", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "13"=>{"name"=>"/var/log/audit", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "14"=>{"name"=>"/var/tmp", "value"=>"[FILTERED]", "parameter_type"=>"string"}}, "compute_attributes"=>{"flavor_id"=>"t3.small", "image_id"=>"ami-061a46908ff969da5", "subnet_id"=>"subnet-06a06d16b7ef6b047", "security_group_ids"=>["sg-0542a7ea59b8f51de", "sg-09dac7d65b7a96b1c"], "managed_ip"=>"private"}}, "apiv"=>"v2"}
2025-01-22T20:08:11 [I|app|3329381c] Started POST "/api/v2/hosts" for x.x.x.x at 2025-01-22 20:08:11 +0000
2025-01-22T20:08:11 [I|app|5ebc7423] Started POST "/api/v2/hosts" for x.x.x.x at 2025-01-22 20:08:11 +0000
2025-01-22T20:08:11 [I|app|5ebc7423] Processing by Api::V2::HostsController#create as JSON
2025-01-22T20:08:11 [I|app|5ebc7423]   Parameters: {"host"=>{"managed"=>"true", "ip"=>nil, "compute_resource_id"=>1, "compute_profile_id"=>57, "subnet_id"=>nil, "domain_name"=>"yul1.qprod.net", "domain_id"=>1, "hostgroup_id"=>340, "interfaces_attributes"=>nil, "name"=>"empty-test-box1-app", "build"=>"1", "enabled"=>"1", "location_id"=>3, "organization_id"=>1, "host_parameters_attributes"=>{"0"=>{"name"=>"t3_m4", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "1"=>{"name"=>"aws_access_key_id", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "2"=>{"name"=>"aws_secret_access_key", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "3"=>{"name"=>"facts", "value"=>"[FILTERED]", "parameter_type"=>"hash"}, "4"=>{"name"=>"subnet", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "5"=>{"name"=>"disk_size", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "6"=>{"name"=>"disk_iops", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "7"=>{"name"=>"disk_throughput", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "8"=>{"name"=>"logical_volumes", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "9"=>{"name"=>"swap", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "10"=>{"name"=>"/mnt/data1", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "11"=>{"name"=>"/var/lib/docker", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "12"=>{"name"=>"/var/log", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "13"=>{"name"=>"/var/log/audit", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "14"=>{"name"=>"/var/tmp", "value"=>"[FILTERED]", "parameter_type"=>"string"}}, "compute_attributes"=>{"flavor_id"=>"t3.small", "image_id"=>"ami-061a46908ff969da5", "subnet_id"=>"subnet-07e2e3b3174ac2f54", "security_group_ids"=>["sg-0542a7ea59b8f51de", "sg-09dac7d65b7a96b1c"], "managed_ip"=>"private"}}, "apiv"=>"v2"}
2025-01-22T20:08:11 [I|app|3329381c] Processing by Api::V2::HostsController#create as JSON
2025-01-22T20:08:11 [I|app|3329381c]   Parameters: {"host"=>{"managed"=>"true", "ip"=>nil, "compute_resource_id"=>1, "compute_profile_id"=>57, "subnet_id"=>nil, "domain_name"=>"yul1.qprod.net", "domain_id"=>1, "hostgroup_id"=>340, "interfaces_attributes"=>nil, "name"=>"empty-test-box3-app", "build"=>"1", "enabled"=>"1", "location_id"=>3, "organization_id"=>1, "host_parameters_attributes"=>{"0"=>{"name"=>"t3_m4", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "1"=>{"name"=>"aws_access_key_id", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "2"=>{"name"=>"aws_secret_access_key", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "3"=>{"name"=>"facts", "value"=>"[FILTERED]", "parameter_type"=>"hash"}, "4"=>{"name"=>"subnet", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "5"=>{"name"=>"disk_size", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "6"=>{"name"=>"disk_iops", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "7"=>{"name"=>"disk_throughput", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "8"=>{"name"=>"logical_volumes", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "9"=>{"name"=>"swap", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "10"=>{"name"=>"/mnt/data1", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "11"=>{"name"=>"/var/lib/docker", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "12"=>{"name"=>"/var/log", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "13"=>{"name"=>"/var/log/audit", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "14"=>{"name"=>"/var/tmp", "value"=>"[FILTERED]", "parameter_type"=>"string"}}, "compute_attributes"=>{"flavor_id"=>"t3.small", "image_id"=>"ami-061a46908ff969da5", "subnet_id"=>"subnet-04dbc168245aca015", "security_group_ids"=>["sg-0542a7ea59b8f51de", "sg-09dac7d65b7a96b1c"], "managed_ip"=>"private"}}, "apiv"=>"v2"}
2025-01-22T20:08:11 [I|app|ab5f6644] Started POST "/api/v2/hosts" for x.x.x.x at 2025-01-22 20:08:11 +0000
2025-01-22T20:08:11 [I|app|ab5f6644] Processing by Api::V2::HostsController#create as JSON
2025-01-22T20:08:11 [I|app|ab5f6644]   Parameters: {"host"=>{"managed"=>"true", "ip"=>nil, "compute_resource_id"=>1, "compute_profile_id"=>57, "subnet_id"=>nil, "domain_name"=>"yul1.qprod.net", "domain_id"=>1, "hostgroup_id"=>340, "interfaces_attributes"=>nil, "name"=>"empty-test-box4-app", "build"=>"1", "enabled"=>"1", "location_id"=>3, "organization_id"=>1, "host_parameters_attributes"=>{"0"=>{"name"=>"t3_m4", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "1"=>{"name"=>"aws_access_key_id", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "2"=>{"name"=>"aws_secret_access_key", "secret"=>"[FILTERED]", "value"=>"[FILTERED]"}, "3"=>{"name"=>"facts", "value"=>"[FILTERED]", "parameter_type"=>"hash"}, "4"=>{"name"=>"subnet", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "5"=>{"name"=>"disk_size", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "6"=>{"name"=>"disk_iops", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "7"=>{"name"=>"disk_throughput", "value"=>"[FILTERED]", "parameter_type"=>"integer"}, "8"=>{"name"=>"logical_volumes", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "9"=>{"name"=>"swap", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "10"=>{"name"=>"/mnt/data1", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "11"=>{"name"=>"/var/lib/docker", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "12"=>{"name"=>"/var/log", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "13"=>{"name"=>"/var/log/audit", "value"=>"[FILTERED]", "parameter_type"=>"string"}, "14"=>{"name"=>"/var/tmp", "value"=>"[FILTERED]", "parameter_type"=>"string"}}, "compute_attributes"=>{"flavor_id"=>"t3.small", "image_id"=>"ami-061a46908ff969da5", "subnet_id"=>"subnet-07e2e3b3174ac2f54", "security_group_ids"=>["sg-0542a7ea59b8f51de", "sg-09dac7d65b7a96b1c"], "managed_ip"=>"private"}}, "apiv"=>"v2"}
4

I’m confused about your setup. Are these 8 Foreman instances connected somehow?

5

They are just federated across different regions around the world, some are production, pre-production, testing, and operations.

6

Do you see a traceback directly after this error in production.log? would be helpful to know exactly what’s trying to find this host and how it’s failing.

7
Summary 
2025-01-22T20:39:21 [I|app|bf3a0aa6] Backtrace for 'Failed to launch script on empty-test-box103-app.g1-cmh.qops.net: Couldn't find Host::Managed with 'id'=3632 [WHERE "hosts"."type" = $1]' error (ActiveRecord::RecordNotFound): Couldn't find Host::Managed with 'id'=3632 [WHERE "hosts"."type" = $1]
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/relation/finder_methods.rb:357:in `raise_record_not_found_exception!'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/relation/finder_methods.rb:476:in `find_one'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/relation/finder_methods.rb:458:in `find_with_ids'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/relation/finder_methods.rb:69:in `find'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/querying.rb:22:in `find'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/core.rb:340:in `find'
 bf3a0aa6 | /usr/share/foreman/app/models/host.rb:33:in `method_missing'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/orchestration/ssh_provision.rb:66:in `setSSHProvision'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/orchestration.rb:220:in `execute'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/orchestration.rb:149:in `block in process'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/orchestration.rb:141:in `each'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/orchestration.rb:141:in `process'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/orchestration.rb:53:in `post_commit'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:427:in `block in make_lambda'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:270:in `block in simple'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:516:in `block in invoke_after'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:516:in `each'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:516:in `invoke_after'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:107:in `run_callbacks'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:824:in `_run_commit_callbacks'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/transactions.rb:321:in `committed!'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/connection_adapters/abstract/transaction.rb:155:in `commit_records'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/connection_adapters/abstract/transaction.rb:304:in `block in commit_transaction'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/connection_adapters/abstract/transaction.rb:294:in `commit_transaction'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/connection_adapters/abstract/transaction.rb:351:in `block in within_new_transaction'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/transactions.rb:298:in `save'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/suppressor.rb:44:in `save'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/foreman/sti.rb:20:in `save'
 bf3a0aa6 | /usr/share/foreman/app/controllers/api/v2/hosts_controller.rb:148:in `create'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/abstract_controller/base.rb:228:in `process_action'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal/rendering.rb:30:in `process_action'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
 bf3a0aa6 | /usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 bf3a0aa6 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 bf3a0aa6 | /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 bf3a0aa6 | /usr/share/gems/gems/audited-5.7.0/lib/audited/sweeper.rb:16:in `around'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 bf3a0aa6 | /usr/share/gems/gems/audited-5.7.0/lib/audited/sweeper.rb:16:in `around'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:137:in `run_callbacks'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/abstract_controller/callbacks.rb:41:in `process_action'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal/rescue.rb:22:in `process_action'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/notifications.rb:203:in `block in instrument'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/notifications.rb:203:in `instrument'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal/params_wrapper.rb:249:in `process_action'
 bf3a0aa6 | /usr/share/gems/gems/activerecord-6.1.7.10/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/abstract_controller/base.rb:165:in `process'
 bf3a0aa6 | /usr/share/gems/gems/actionview-6.1.7.10/lib/action_view/rendering.rb:39:in `process'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal.rb:190:in `dispatch'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_controller/metal.rb:254:in `dispatch'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/routing/route_set.rb:33:in `serve'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/routing/mapper.rb:49:in `serve'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/journey/router.rb:50:in `block in serve'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/journey/router.rb:32:in `each'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/journey/router.rb:32:in `serve'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/routing/route_set.rb:842:in `call'
 bf3a0aa6 | /usr/share/gems/gems/apipie-dsl-2.6.2/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
 bf3a0aa6 | /usr/share/gems/gems/apipie-rails-1.4.2/lib/apipie/static_dispatcher.rb:74:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/static.rb:24:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/static.rb:24:in `call'
 bf3a0aa6 | /usr/share/foreman/lib/foreman/middleware/libvirt_connection_cleaner.rb:9:in `call'
 bf3a0aa6 | /usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
 bf3a0aa6 | /usr/share/gems/gems/apipie-rails-1.4.2/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/tempfile_reaper.rb:15:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/etag.rb:27:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/conditional_get.rb:40:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/head.rb:12:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/http/permissions_policy.rb:22:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/http/content_security_policy.rb:19:in `call'
 bf3a0aa6 | /usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:266:in `context'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:260:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/cookies.rb:697:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/callbacks.rb:98:in `run_callbacks'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
 bf3a0aa6 | /usr/share/gems/gems/railties-6.1.7.10/lib/rails/rack/logger.rb:37:in `call_app'
 bf3a0aa6 | /usr/share/gems/gems/railties-6.1.7.10/lib/rails/rack/logger.rb:28:in `call'
 bf3a0aa6 | /usr/share/gems/gems/sprockets-rails-3.5.2/lib/sprockets/rails/quiet_assets.rb:17:in `call'
 bf3a0aa6 | /usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/request_id.rb:26:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/method_override.rb:24:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/runtime.rb:22:in `call'
 bf3a0aa6 | /usr/share/gems/gems/activesupport-6.1.7.10/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/executor.rb:14:in `call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/sendfile.rb:110:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/ssl.rb:77:in `call'
 bf3a0aa6 | /usr/share/gems/gems/actionpack-6.1.7.10/lib/action_dispatch/middleware/host_authorization.rb:142:in `call'
 bf3a0aa6 | /usr/share/gems/gems/secure_headers-6.7.0/lib/secure_headers/middleware.rb:11:in `call'
 bf3a0aa6 | /usr/share/gems/gems/railties-6.1.7.10/lib/rails/engine.rb:539:in `call'
 bf3a0aa6 | /usr/share/gems/gems/railties-6.1.7.10/lib/rails/railtie.rb:207:in `public_send'
 bf3a0aa6 | /usr/share/gems/gems/railties-6.1.7.10/lib/rails/railtie.rb:207:in `method_missing'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:74:in `block in call'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `each'
 bf3a0aa6 | /usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `call'
 bf3a0aa6 | /usr/share/gems/gems/puma-6.4.3/lib/puma/configuration.rb:272:in `call'
 bf3a0aa6 | /usr/share/gems/gems/puma-6.4.3/lib/puma/request.rb:100:in `block in handle_request'
 bf3a0aa6 | /usr/share/gems/gems/puma-6.4.3/lib/puma/thread_pool.rb:378:in `with_force_shutdown'
 bf3a0aa6 | /usr/share/gems/gems/puma-6.4.3/lib/puma/request.rb:99:in `handle_request'
 bf3a0aa6 | /usr/share/gems/gems/puma-6.4.3/lib/puma/server.rb:464:in `process_client'
 bf3a0aa6 | /usr/share/gems/gems/puma-6.4.3/lib/puma/server.rb:245:in `block in run'
 bf3a0aa6 | /usr/share/gems/gems/puma-6.4.3/lib/puma/thread_pool.rb:155:in `block in spawn_thread'
 bf3a0aa6 | /usr/share/gems/gems/logging-2.4.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2025-01-22T20:39:21 [W|app|bf3a0aa6] Rolling back due to a problem: [#<Orchestration::Task:0x00007f789e1d2630 @name="Configure instance empty-test-box103-app.g1-cmh.qops.net via SSH", @id="Configure instance empty-test-box103-app.g1-cmh.qops.net via SSH", @status="failed", @priority=2003, @action=[#<Host::Managed id: 3632, name: "empty-test-box103-app.g1-cmh.qops.net", last_compile: nil, last_report: nil, updated_at: "2025-01-22 20:38:28.169573372 +0000", created_at: "2025-01-22 20:38:28.169573372 +0000", root_pass: nil, architecture_id: 1, operatingsystem_id: 18, ptable_id: nil, medium_id: nil, build: true, comment: "", disk: nil, installed_at: nil, model_id: nil, hostgroup_id: 435, owner_id: 4, owner_type: "User", enabled: true, puppet_ca_proxy_id: nil, managed: true, use_image: nil, image_file: nil, uuid: "i-038fb32938118a3a1", compute_resource_id: 1, puppet_proxy_id: nil, certname: nil, image_id: 27, organization_id: 1, location_id: 3, type: nil, otp: nil, realm_id: nil, compute_profile_id: 57, provision_method: nil, grub_pass: nil, discovery_rule_id: nil, global_status: 0, lookup_value_matcher: [FILTERED], pxe_loader: nil, initiated_at: nil, build_errors: nil, creator_id: 4>, :setSSHProvision], @created=1737578301.6946926, @timestamp=2025-01-22 20:39:21.539405014 UTC>]
8

I suspect there is a bug in the way the API is handling POST requests that come in rapidly in parallel with 3.13 that didn’t exist in 3.7 (so somewhere between 3.7 and 3.13 as we jumped straight to 3.13)

9

It looks like it can’t find the host while running a method called setSSHProvision here:

I will leave it to folks with more provisioning expertise as to why that may be happening. cc @Shimon_Shtein @lstejska