Bug 1385495

Summary:	Failure in VM provisioning on REV (parse_error_response)
Product:	Red Hat CloudForms Management Engine	Reporter:	Prasad Mukhedkar <pmukhedk>
Component:	Providers	Assignee:	Juan Hernández <juan.hernandez>
Status:	CLOSED NOTABUG	QA Contact:	Dave Johnson <dajohnso>
Severity:	urgent	Docs Contact:
Priority:	urgent
Version:	5.7.0	CC:	jfrey, jhardy, obarenbo, pmukhedk
Target Milestone:	GA
Target Release:	cfme-future
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-10-27 12:44:17 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	RHEVM	Target Upstream Version:

Description Prasad Mukhedkar 2016-10-17 08:15:14 UTC

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

Comment 3 Juan Hernández 2016-10-27 11:04:18 UTC

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?