Problem:
Hello everyone,
I am trying to create a VM on our Xen Orchestra infra. While it works when using the webUI it doesn’t when using the API. Any hint will be very appriciated cause I am stumbling in the dark.
The calls are done through Postman. If I use another pool the error message is different and more cryptic.
Thank you in advance.
The error message is:
{
"error": {
"id": null,
"errors": {
"base": [
"Failed to create a compute Pool D1 (Xenserver) instance vm.example.org: VDI.destroy: [\"HANDLE_INVALID\", \"VDI\", \"OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de\"]\n "
]
},
"full_messages": [
"Failed to create a compute Pool D1 (Xenserver) instance vm.example.org: VDI.destroy: [\"HANDLE_INVALID\", \"VDI\", \"OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de\"]\n "
]
}
}
Here the input json:
{
"location_id": 2,
"organization_id": 1,
"host": {
"name": "vm.example.org",
"ip": "10.1.1.1",
"location_id": 2,
"organization_id": 1,
"environment_id": 1,
"architecture_id": 1,
"domain_id": 1,
"puppet_proxy_id": 1,
"puppet_ca_proxy_id": 1,
"hostgroup_id": 4,
"operatingsystem_id": 14,
"ptable_id": 122,
"compute_resource_id": 7,
"root_pass": "[REDACTED]",
"owner_id": 12,
"owner_type": "User",
"pxe_loader": "PXELinux BIOS",
"type": "Host::Managed",
"model_id": 1,
"build": 1,
"enabled": 1,
"provision_method": "build",
"medium_id": 2,
"managed": "true",
"host_parameters_attributes": [
{
"name": "applications",
"parameter_type": "string",
"value": "test",
"hidden_value": 0,
"_destroy": "false"
},{
"name": "customer",
"parameter_type": "string",
"value": "customer",
"hidden_value": 0,
"_destroy": "false"
}
],
"interfaces_attributes": [
{
"ip": "10.1.1.1",
"ip6": "",
"type": "Nic::Managed",
"name": "vm",
"subnet_id": 1,
"domain_id": 1,
"managed": 1,
"primary": 1,
"provision": 1,
"virtual": 0,
"compute_attributes": {
"network": "<UUID>"
}
}
],
"compute_attributes": {
"vcpus_max": 2,
"memory_min": "4294967296",
"memory_max": "4294967296",
"start": 1,
"iso": "",
"builtin_template": "<UUID>",
"volumes_attributes": {
"4": {
"sr": "<UUID>",
"virtual_size_gb": "50"
}}}}}
Expected outcome:
The VM is created.
Foreman and Proxy versions:
Foreman: 2.1.2
Proxy: 2.1.2
Foreman and Proxy plugin versions:
foreman_column_view 0.4.0
foreman_hooks 0.3.16
foreman_xen 1.0.1
Distribution and version:
Debian 10.9
Other relevant data:
foreman debug log:
Strangly the hash contains two disks of different size.
2021-06-08T14:44:57 [I|app|4afd1906] Started POST "/api/hosts" for 10.0.0.5 at 2021-06-08 14:44:57 +0200
2021-06-08T14:44:57 [I|app|4afd1906] Processing by Api::V2::HostsController#create as JSON
2021-06-08T14:44:57 [I|app|4afd1906] Parameters: {"location_id"=>2, "organization_id"=>1, "host"=>{"name"=>"vm.example.org", "ip"=>"10.1.1.1", "location_id"=>2, "organization_id"=>1, "environment_id"=>1, "architecture_id"=>1, "domain_id"=>1, "puppet_proxy_id"=>1, "puppet_ca_proxy_id"=>1, "hostgroup_id"=>4, "operatingsystem_id"=>14, "ptable_id"=>122, "compute_resource_id"=>7, "root_pass"=>"[FILTERED]", "owner_id"=>12, "owner_type"=>"User", "pxe_loader"=>"PXELinux BIOS", "type"=>"Host::Managed", "model_id"=>1, "build"=>1, "enabled"=>1, "provision_method"=>"build", "medium_id"=>2, "managed"=>"true", "host_parameters_attributes"=>[{"name"=>"applications", "parameter_type"=>"string", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}, {"name"=>"customer", "parameter_type"=>"string", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}, {"name"=>"sla", "parameter_type"=>"string", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}, {"name"=>"backup", "parameter_type"=>"string", "value"=>"[FILTERED]", "hidden_value"=>"[FILTERED]", "_destroy"=>"false"}], "interfaces_attributes"=>[{"ip"=>"10.1.2.23", "ip6"=>"", "type"=>"Nic::Managed", "name"=>"vm", "subnet_id"=>1, "domain_id"=>1, "managed"=>1, "primary"=>1, "provision"=>1, "virtual"=>0, "compute_attributes"=>{"network"=>"b9a3d464-e7a9-2c2f-f64f-d72bbb532753"}}], "compute_attributes"=>{"vcpus_max"=>2, "memory_min"=>"4294967296", "memory_max"=>"4294967296", "start"=>1, "iso"=>"", "builtin_template"=>"bac315b4-66fd-4488-82f5-9808e927b4b9", "volumes_attributes"=>{"4"=>{"sr"=>"2e9a29de-d6d3-ba81-3ba4-ff383270a12b", "virtual_size_gb"=>"50"}}}}, "apiv"=>"v2"}
2021-06-08T14:44:57 [D|tax|4afd1906] Current location set to Default Location
2021-06-08T14:44:57 [D|tax|4afd1906] Current organization set to Default Organization
2021-06-08T14:44:57 [D|app|4afd1906] Scheduling new DHCP reservations for vm.example.org
2021-06-08T14:44:57 [D|app|4afd1906] Enqueued task 'dhcp_create_10.1.1.1' to 'Host::Managed Main' queue
2021-06-08T14:44:57 [D|tax|4afd1906] Current organization set to Default Organization
2021-06-08T14:44:57 [D|tax|4afd1906] Current location set to Default Location
2021-06-08T14:44:57 [D|tax|4afd1906] Current location set to Default Location
2021-06-08T14:44:57 [D|tax|4afd1906] Current organization set to Default Organization
2021-06-08T14:44:57 [D|app|4afd1906] Enqueued task 'Deploy TFTP PXELinux config for vm.example.org' to 'Host::Managed Main' queue
2021-06-08T14:44:57 [D|app|4afd1906] Enqueued task 'Deploy TFTP PXEGrub2 config for vm.example.org' to 'Host::Managed Main' queue
2021-06-08T14:44:57 [D|app|4afd1906] Enqueued task 'Deploy TFTP PXEGrub config for vm.example.org' to 'Host::Managed Main' queue
2021-06-08T14:44:57 [D|app|4afd1906] Enqueued task 'Deploy TFTP iPXE config for vm.example.org' to 'Host::Managed Main' queue
2021-06-08T14:44:57 [D|app|4afd1906] Enqueued task 'Fetch TFTP boot files for vm.example.org' to 'Host::Managed Main' queue
2021-06-08T14:44:58 [D|app|4afd1906] Enqueued task 'Set up compute instance vm.example.org' to 'Host::Managed Main' queue
2021-06-08T14:44:58 [D|app|4afd1906] Enqueued task 'Query instance details for vm.example.orge' to 'Host::Managed Main' queue
2021-06-08T14:44:58 [D|app|4afd1906] Enqueued task 'Cleanup PuppetCA certificates for vm.example.org' to 'Host::Managed Post' queue
2021-06-08T14:44:58 [D|app|4afd1906] Enqueued task 'Enable PuppetCA autosigning for vm.example.org' to 'Host::Managed Post' queue
2021-06-08T14:44:58 [D|app|4afd1906] Observed create hook on vm.example.org
2021-06-08T14:44:58 [D|app|4afd1906] Observed postcreate hook on vm.example.org
2021-06-08T14:44:58 [D|app|4afd1906] Queuing 2 hooks for Host::Managed#postcreate
2021-06-08T14:44:58 [D|app|4afd1906] Queuing hook /usr/share/foreman/config/hooks/host/managed/postcreate/01_set_xen_host_description.sh for Host::Managed#postcreate at priority 01
2021-06-08T14:44:58 [D|app|4afd1906] Enqueued task 'Hook: /usr/share/foreman/config/hooks/host/managed/postcreate/01_set_xen_host_description.sh' to 'Host::Managed Post' queue
2021-06-08T14:44:58 [D|app|4afd1906] Queuing hook /usr/share/foreman/config/hooks/host/managed/postcreate/02_set_xen_host_tags.sh for Host::Managed#postcreate at priority 02
2021-06-08T14:44:58 [D|app|4afd1906] Enqueued task 'Hook: /usr/share/foreman/config/hooks/host/managed/postcreate/02_set_xen_host_tags.sh' to 'Host::Managed Post' queue
2021-06-08T14:44:58 [D|app|4afd1906] Processing task 'Set up compute instance vm.example.org' from 'Host::Managed Main'
2021-06-08T14:44:58 [I|app|4afd1906] Adding Compute instance for vm.example.org
2021-06-08T14:44:58 [D|app|4afd1906] create_vm args:
2021-06-08T14:44:58 [D|app|4afd1906] <Hash> {:vcpus_max=>2, :memory_min=>"4294967296", :memory_max=>"4294967296", :iso=>"", :start=>1, :target_sr=>"4810ecd5-743b-008e-785c-83c2c7ee7d31", :builtin_template=>"bac315b4-66fd-4488-82f5-9808e927b4b9", :volumes_attributes=>{:"1606145379158"=>{:sr=>"2e9a29de-d6d3-ba81-3ba4-ff383270a12b", :virtual_size_gb=>"100"}, :"4"=>{:sr=>"2e9a29de-d6d3-ba81-3ba4-ff383270a12b", :virtual_size_gb=>"50"}}, :name=>"vm.example.org", :provision_method=>"build", :firmware_type=>:bios, :interfaces_attributes=>{:"0"=>{:network=>"b9a3d464-e7a9-2c2f-f64f-d72bbb532753", :ip=>"10.1.2.23", :ip6=>""}}, :name_description=>nil, :is_a_template=>false, :is_a_shapshot=>false, :xenstore=>{:"vm-data"=>{:ifs=>{:"0"=>{:ip=>"10.1.1.1", :gateway=>"10.1.1.1", :netmask=>"255.255.0.0"}}}, :nameserver1=>"10.1.1.0", :nameserver2=>"10.1.1.2", :environment=>"production"}, :network_data=>{:links=>[{:type=>"phy", :id=>nil, :name=>nil, :mtu=>1500}], :networks=>[{:id=>"network0", :routes=>[{:network=>"0.0.0.0", :netmask=>"0.0.0.0", :gateway=>"10.1.1.254"}], :ip_address=>"10.1.1.1", :type=>"ipv4", :netmask=>"255.255.0.0", :link=>nil}], :services=>[{:type=>"dns", :address=>"10.1.1.0"}, {:type=>"dns", :address=>"10.1.1.2"}]}}
2021-06-08T14:45:40 [W|app|4afd1906] Failed to create a compute Pool D1 (Xenserver) instance vm.example.org: VDI.destroy: ["HANDLE_INVALID", "VDI", "OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de"]
2021-06-08T14:45:40 [D|app|4afd1906] Backtrace for 'Failed to create a compute Pool D1 (Xenserver) instance vm.example.org: VDI.destroy: ["HANDLE_INVALID", "VDI", "OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de"]
' error (Fog::XenServer::RequestFailed): VDI.destroy: ["HANDLE_INVALID", "VDI", "OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de"]
/usr/share/foreman/vendor/ruby/2.5.0/gems/fog-xenserver-1.0.0/lib/fog/xenserver/connection.rb:55:in `request'
/usr/share/foreman/vendor/ruby/2.5.0/gems/fog-xenserver-1.0.0/lib/fog/xenserver/compute/requests/destroy_record.rb:6:in `destroy_record'
/usr/share/foreman/vendor/ruby/2.5.0/gems/fog-xenserver-1.0.0/lib/fog/xenserver/compute/models/vdi.rb:56:in `destroy'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_xen-1.0.1/app/models/foreman_xen/xenserver.rb:340:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_xen-1.0.1/app/models/foreman_xen/xenserver.rb:340:in `rescue in create_vm'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_xen-1.0.1/app/models/foreman_xen/xenserver.rb:289:in `create_vm'
/usr/share/foreman/app/models/concerns/orchestration/compute.rb:91:in `setCompute'
/usr/share/foreman/app/models/concerns/orchestration.rb:220:in `execute'
/usr/share/foreman/app/models/concerns/orchestration.rb:145:in `block in process'
/usr/share/foreman/app/models/concerns/orchestration.rb:137:in `each'
/usr/share/foreman/app/models/concerns/orchestration.rb:137:in `process'
/usr/share/foreman/app/models/concerns/orchestration.rb:44:in `around_save_orchestration'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:139:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:825:in `_run_save_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/callbacks.rb:327:in `create_or_update'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/timestamp.rb:128:in `create_or_update'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/persistence.rb:470:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/validations.rb:47:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/transactions.rb:314:in `block in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/transactions.rb:375:in `block in with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/connection_adapters/abstract/database_statements.rb:280:in `block in transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/connection_adapters/abstract/transaction.rb:280:in `block in within_new_transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/connection_adapters/abstract/transaction.rb:278:in `within_new_transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/connection_adapters/abstract/database_statements.rb:280:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/transactions.rb:212:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/transactions.rb:366:in `with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/transactions.rb:314:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/suppressor.rb:44:in `save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:26:in `save'
/usr/share/foreman/app/controllers/api/v2/hosts_controller.rb:144:in `create'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/abstract_controller/base.rb:195:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:112:in `block in run_callbacks'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:163:in `disable_json_root'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:139:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/notifications.rb:180:in `block in instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/notifications.rb:180:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.3/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/abstract_controller/base.rb:136:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionview-6.0.3.3/lib/action_view/rendering.rb:39:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal.rb:190:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_controller/metal.rb:254:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/routing/route_set.rb:33:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/routing/mapper.rb:18:in `block in <class:Constraints>'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/journey/router.rb:32:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/journey/router.rb:32:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/routing/route_set.rb:834:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-dsl-2.2.10/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/static_dispatcher.rb:66:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/extractor/recorder.rb:137:in `call'
/usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/cookies.rb:648:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/callbacks.rb:101:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.3/lib/rails/rack/logger.rb:37:in `call_app'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.3/lib/rails/rack/logger.rb:28:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sprockets-rails-3.2.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/static.rb:126:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.3/lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/secure_headers-6.3.1/lib/secure_headers/middleware.rb:11:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.3/lib/rails/engine.rb:527:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.3/lib/rails/railtie.rb:190:in `public_send'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.3/lib/rails/railtie.rb:190:in `method_missing'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:160:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'
/usr/share/foreman/vendor/ruby/2.5.0/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2021-06-08T14:45:40 [W|app|4afd1906] Rolling back due to a problem: [#<Orchestration::Task:0x00007fe4981b1c58 @name="Set up compute instance vm.example.org", @id="Set up compute instance vm.example.org", @status="failed", @priority=3, @action=[#<Host::Managed id: nil, name: "vm.example.org", last_compile: nil, last_report: nil, updated_at: nil, created_at: nil, root_pass: [FILTERED], architecture_id: 1, operatingsystem_id: 14, environment_id: 1, ptable_id: 122, medium_id: 2, build: true, comment: nil, disk: nil, installed_at: nil, model_id: 1, hostgroup_id: 4, owner_id: 12, owner_type: "User", enabled: true, puppet_ca_proxy_id: 1, managed: true, use_image: nil, image_file: nil, uuid: nil, compute_resource_id: 7, puppet_proxy_id: 1, certname: nil, image_id: nil, organization_id: 1, location_id: 2, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: 5, provision_method: "build", grub_pass: "$6$zcMdQqyKEgRIlCmN$yuV.HGlna7kUOewQk8vTSnOEaVwwb6...", global_status: 0, lookup_value_matcher: [FILTERED], pxe_loader: "PXELinux BIOS", initiated_at: nil, build_errors: nil>, :setCompute], @created=1623156298.102863, @timestamp=2021-06-08 12:45:40 UTC>]
2021-06-08T14:45:40 [I|app|4afd1906] Processed 1 tasks from queue 'Host::Managed Main', completed 0/8
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Set up compute instancevm.example.org' *failed*
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Query instance details for vm.example.org' *canceled*
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Create DHCP Settings for vm.example.org' *canceled*
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Deploy TFTP PXELinux config for vm.example.org' *canceled*
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Deploy TFTP PXEGrub2 config for vm.example.org' *canceled*
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Deploy TFTP PXEGrub config for vm.example.org' *canceled*
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Deploy TFTP iPXE config for vm.example.org' *canceled*
2021-06-08T14:45:40 [E|app|4afd1906] Task 'Fetch TFTP boot files for vm.example.org' *canceled*
2021-06-08T14:45:40 [E|app|4afd1906] Unprocessable entity Host::Managed (id: new):
Failed to create a compute Pool D1 (Xenserver) instance vm.example.org: VDI.destroy: ["HANDLE_INVALID", "VDI", "OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de"]
2021-06-08T14:45:40 [I|app|4afd1906] Rendering api/v2/errors/unprocessable_entity.json.rabl within api/v2/layouts/error_layout
2021-06-08T14:45:40 [I|app|4afd1906] Rendered api/v2/errors/unprocessable_entity.json.rabl within api/v2/layouts/error_layout (Duration: 7.1ms | Allocations: 5077)
2021-06-08T14:45:40 [D|app|4afd1906] Body: {
"error": {"id":null,"errors":{"base":["Failed to create a compute Pool D1 (Xenserver) instance vm.example.org: VDI.destroy: [\"HANDLE_INVALID\", \"VDI\", \"OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de\"]\n "]},"full_messages":["Failed to create a compute Pool D1 (Xenserver) instance vm.example.org: VDI.destroy: [\"HANDLE_INVALID\", \"VDI\", \"OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de\"]\n "]}
}
2021-06-08T14:45:40 [I|app|4afd1906] Completed 422 Unprocessable Entity in 42800ms (Views: 14.7ms | ActiveRecord: 41.1ms | Allocations: 11980812)
Xen Orchestra debug log:
Jun 8 14:45:12 server01 xapi: [debug||70127937 INET :::80|VDI.create R:96776f988ec3|xapi_sr] OpaqueRef:81c
a3d48-6a62-4a76-89c2-e4f7890524de snapshot_of <- OpaqueRef:NULL
Jun 8 14:45:12 server01 xapi: [debug||70127937 INET :::80|VDI.create R:96776f988ec3|xapi] Unmarking SR aft
er VDI.create (task=OpaqueRef:96776f98-8ec3-4b93-8654-49892050f677)
Jun 8 14:45:12 server01 xapi: [debug||70127937 INET :::80|VBD.create R:b2bb15b27828|audit] VBD.create: VM
= '9d7f6341-c723-661f-dcc4-b7f1a2d5c1cd (vm.example.org)'; VDI = '4b913c98-cb69-4f0e-b25d-06efc5c9b09
6'
Jun 8 14:45:12 server01 xapi: [debug||70127937 INET :::80|VBD.create R:b2bb15b27828|xapi] Checking whether
there's a migrate in progress...
Jun 8 14:45:12 server01 xapi: [debug||70127937 INET :::80|VBD.create R:b2bb15b27828|xapi] VBD.create (devi
ce = 0; uuid = 6c4ea809-dae4-523f-815d-5cb2efd3457f; ref = OpaqueRef:24d99df7-e3fd-43cd-8aed-8c350f91af5d)
[...]
Jun 8 14:45:33 server01 xapi: [debug||70128219 ||dummytaskhelper] task VDI.destroy D:cdcf0034e299 created
by task R:4a7a4eac1cff
Jun 8 14:45:33 server01 xapi: [debug||70128219 |VDI.destroy D:cdcf0034e299|sm] SM lvmoiscsi vdi_delete sr=OpaqueRef:f727d90d-6638-4109-9fd8-7a98ae566763 vdi=OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de
Jun 8 14:45:33 server01 xapi: [ info||70128219 |sm_exec D:d6a0c75e874c|xapi] Session.create trackid=5888d0da9663f8b901760cb60a407c9c pool=false uname= originator=xapi is_local_superuser=true auth_user_sid= parent=trackid=9834f5af41c964e225f24279aefe4e49
[...]
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] VDI.destroy R:90ef0c2704b0 failed with exception Db_exn.DBCache_NotFound("missing row", "VDI", "OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de")
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] Raised Db_exn.DBCache_NotFound("missing row", "VDI", "OpaqueRef:81ca3d48-6a62-4a76-89c2-e4f7890524de")
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] 1/6 xapi Raised at file ocaml/xapi/rbac.ml, line 236
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] 2/6 xapi Called from file ocaml/xapi/server_helpers.ml, line 83
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] 3/6 xapi Called from file ocaml/xapi/server_helpers.ml, line 99
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] 4/6 xapi Called from file lib/xapi-stdext-pervasives/pervasiveext.ml, line 24
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] 5/6 xapi Called from file map.ml, line 135
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace] 6/6 xapi Called from file sexp_conv.ml, line 147
Jun 8 14:45:40 server01 xapi: [error||70127937 INET :::80||backtrace]