Hide Forgot
Provision VM from template, from CF side ends up with VM created on RHV side, but it fails to start the vm. cfme-5.6.2.1-1.el7cf.x86_64 RHV-4.0.4.2-0.1.el7ev How reproducible: Always Steps to Reproduce: Provision VM from template on RHV-4.0.4 Actual results: VM is created at rhev side but the cloudforms provisining request fails with error reporting parsing error Expected results: VM should be created. Additional info: ERRORs in evm.log [----] E, [2016-10-17T03:12:57.900336 #13446:9b198c] ERROR -- : Q-task_id([miq_provision_99000000000001]) <RHEVM> Ovirt::Service#parse_error_response Return from URL: <https://rhevm4.hosted.local/ovirt-engine/api/vms/61c2aeb0-a275-4692-9990-d29fb293d7a8/4955108a-f49c-4e5d-befe-3045f394d200/creation_status> Data: [----] I, [2016-10-17T03:12:57.900813 #13446:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) Starting Phase <provision_error> [----] E, [2016-10-17T03:12:57.920592 #13446:9b198c] ERROR -- : Q-task_id([miq_provision_99000000000001]) MIQ(ManageIQ::Providers::Redhat::InfraManager::Provision#provision_error) [[Ovirt::MissingResourceError]: Ovirt::MissingResourceError] encountered during phase [poll_clone_complete] [----] E, [2016-10-17T03:12:57.920676 #13446:9b198c] ERROR -- : Q-task_id([miq_provision_99000000000001]) /opt/rh/cfme-gemset/gems/ovirt-0.12.1/lib/ovirt/service.rb:311:in `parse_error_response' [----] I, [2016-10-17T03:13:56.554265 #13455:99d8d8] INFO -- : Q-task_id([miq_provision_99000000000001]) <AutomationEngine> <AEMethod check_provisioned> ProvisionCheck returned <error> for state <finished> and status <Error> [----] I, [2016-10-17T03:13:56.589983 #13455:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) <AutomationEngine> Processed State=[CheckProvisioned] with Result=[error] [----] W, [2016-10-17T03:13:56.590079 #13455:9b198c] WARN -- : Q-task_id([miq_provision_99000000000001]) <AutomationEngine> Error in State=[CheckProvisioned] [----] I, [2016-10-17T03:13:56.590228 #13455:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) <AutomationEngine> In State=[CheckProvisioned], invoking [on_error] method=[update_provision_status(status => '[Ovirt::MissingResourceError]: Ovirt::MissingResourceError')] [----] I, [2016-10-17T03:13:56.599239 #13455:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) <AutomationEngine> Invoking [inline] method [/ManageIQ/I nfrastructure/VM/Provisioning/StateMachines/VMProvision_VM/update_provision_status] with inputs [{"status"=>"[Ovirt::MissingResourceError]: Ovirt::MissingResourceError"}] [----] E, [2016-10-17T03:13:56.977684 #13455:9b198c] ERROR -- : Q-task_id([miq_provision_99000000000001]) MIQ(MiqAeEngine.deliver) Error delivering {"request"=>"vm_provision"} for object [ManageIQ::Providers::Redhat::InfraManager::Provision.99000000000001] with state [CheckProvisioned] to Automate: [----] I, [2016-10-17T03:13:56.977807 #13455:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) MIQ(ManageIQ::Providers::Redhat::InfraManager::Provision#after_ae_delivery) ae_result="error" Complete traceback : [----] E, [2016-10-17T03:12:57.900336 #13446:9b198c] ERROR -- : Q-task_id([miq_provision_99000000000001]) <RHEVM> Ovirt::Service#parse_error_response Return from URL: <https://rhevm4.hosted.local/ovirt-engine/api/vms/61c2aeb0-a275-4692-9990-d29fb293d7a8/4955108a-f49c-4e5d-befe-3045f394d200/creation_status> Data: [----] I, [2016-10-17T03:12:57.900813 #13446:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) Starting Phase <provision_error> [----] E, [2016-10-17T03:12:57.920592 #13446:9b198c] ERROR -- : Q-task_id([miq_provision_99000000000001]) MIQ(ManageIQ::Providers::Redhat::InfraManager::Provision#provision_error) [[Ovirt::MissingResourceError]: Ovirt::MissingResourceError] encountered during phase [poll_clone_complete] [----] E, [2016-10-17T03:12:57.920676 #13446:9b198c] ERROR -- : Q-task_id([miq_provision_99000000000001]) /opt/rh/cfme-gemset/gems/ovirt-0.12.1/lib/ovirt/service.rb:311:in `parse_error_response' /opt/rh/cfme-gemset/gems/ovirt-0.12.1/lib/ovirt/service.rb:282:in `block in resource_verb' /opt/rh/cfme-gemset/gems/rest-client-2.0.0/lib/restclient/request.rb:858:in `call' /opt/rh/cfme-gemset/gems/rest-client-2.0.0/lib/restclient/request.rb:858:in `process_result' /opt/rh/cfme-gemset/gems/rest-client-2.0.0/lib/restclient/request.rb:776:in `block in transmit' /opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:853:in `start' /opt/rh/cfme-gemset/gems/rest-client-2.0.0/lib/restclient/request.rb:766:in `transmit' /opt/rh/cfme-gemset/gems/rest-client-2.0.0/lib/restclient/request.rb:215:in `execute' /opt/rh/cfme-gemset/gems/rest-client-2.0.0/lib/restclient/request.rb:52:in `execute' /opt/rh/cfme-gemset/gems/rest-client-2.0.0/lib/restclient/resource.rb:51:in `get' /opt/rh/cfme-gemset/gems/ovirt-0.12.1/lib/ovirt/service.rb:277:in `resource_verb' /opt/rh/cfme-gemset/gems/ovirt-0.12.1/lib/ovirt/service.rb:251:in `resource_get' /opt/rh/cfme-gemset/gems/ovirt-0.12.1/lib/ovirt/service.rb:161:in `status' /var/www/miq/vmdb/app/models/manageiq/providers/redhat/infra_manager/provision/cloning.rb:7:in `block in clone_complete?' /var/www/miq/vmdb/app/models/mixins/provider_object_mixin.rb:6:in `block in with_provider_connection' /var/www/miq/vmdb/app/models/manageiq/providers/redhat/infra_manager.rb:113:in `with_provider_connection' /var/www/miq/vmdb/app/models/mixins/provider_object_mixin.rb:5:in `with_provider_connection' /var/www/miq/vmdb/app/models/manageiq/providers/redhat/infra_manager/provision/cloning.rb:6:in `clone_complete?' /var/www/miq/vmdb/app/models/manageiq/providers/redhat/infra_manager/provision/state_machine.rb:25:in `poll_clone_complete' /var/www/miq/vmdb/app/models/miq_request_task/state_machine.rb:17:in `signal' /var/www/miq/vmdb/app/models/manageiq/providers/redhat/infra_manager/provision/state_machine.rb:19:in `start_clone_task' /var/www/miq/vmdb/app/models/miq_request_task/state_machine.rb:17:in `signal' /var/www/miq/vmdb/app/models/miq_provision/state_machine.rb:18:in `prepare_provision' /var/www/miq/vmdb/app/models/miq_request_task/state_machine.rb:17:in `signal' /var/www/miq/vmdb/app/models/manageiq/providers/redhat/infra_manager/provision/state_machine.rb:9:in `determine_placement' /var/www/miq/vmdb/app/models/miq_request_task/state_machine.rb:17:in `signal' /var/www/miq/vmdb/app/models/manageiq/providers/redhat/infra_manager/provision/state_machine.rb:3:in `create_destination' /var/www/miq/vmdb/app/models/miq_request_task/state_machine.rb:17:in `signal' /var/www/miq/vmdb/app/models/miq_provision/state_machine.rb:4:in `run_provision' /var/www/miq/vmdb/app/models/miq_request_task/state_machine.rb:17:in `signal' /var/www/miq/vmdb/app/models/miq_provision_task.rb:15:in `do_request' /var/www/miq/vmdb/app/models/miq_request_task.rb:193:in `execute' /var/www/miq/vmdb/app/models/miq_queue.rb:345:in `block in deliver' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:89:in `block in timeout' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `block in catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:34:in `catch' /opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:104:in `timeout' /var/www/miq/vmdb/app/models/miq_queue.rb:341:in `deliver' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker' /var/www/miq/vmdb/app/models/miq_worker.rb:347:in `block in start' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /var/www/miq/vmdb/app/models/miq_worker.rb:345:in `start' /var/www/miq/vmdb/app/models/miq_worker.rb:274:in `start_worker' /var/www/miq/vmdb/app/models/miq_worker.rb:154:in `block in sync_workers' /var/www/miq/vmdb/app/models/miq_worker.rb:154:in `times' /var/www/miq/vmdb/app/models/miq_worker.rb:154:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:52:in `block in sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server.rb:173:in `start' /var/www/miq/vmdb/app/models/miq_server.rb:265:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:92:in `start' /var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>' [----] I, [2016-10-17T03:12:57.971467 #13446:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) Starting Phase <finish> [----] I, [2016-10-17T03:12:57.983252 #13446:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) MIQ(MiqQueue#delivered) Message id: [99000000000091], State: [ok], Delivered in [6.983379662] seconds [----] I, [2016-10-17T03:12:57.985342 #13446:9b198c] INFO -- : Q-task_id([miq_provision_99000000000001]) MIQ(MiqQueue#m_callback) Message id: [99000000000091], Invoking Callback with args: ["ok", "Message delive
Prasad, are you completely sure that you are using version 4.0.4 of RHV? I believe that this issue was fixed in that version of RHV, see bug 1359139. The problem is that the URL for the "creation_status" is incorrect. In your log it is like this: .../vms/123/456/creation_status But it should be like this: .../vms/123/creation_status/456 There is a small chance that this URL is generated within ManageIQ, but I strongly believe it isn't. Can you please double check the version of RHV?