Bug 1217227

Summary:	Failed to create snapshot
Product:	Red Hat CloudForms Management Engine	Reporter:	Thom Carlin <tcarlin>
Component:	SmartState Analysis	Assignee:	Jerry Keselman <jkeselma>
Status:	CLOSED INSUFFICIENT_DATA	QA Contact:	Niyaz Akhtar Ansari <nansari>
Severity:	high	Docs Contact:
Priority:	high
Version:	5.4.0	CC:	cpelland, dajohnso, jhardy, jprause, nansari, obarenbo, tcarlin, vrutkovs
Target Milestone:	GA	Keywords:	ZStream
Target Release:	5.5.4
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:	smartstate:openstack
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-04-21 14:47:29 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Thom Carlin 2015-04-29 19:56:43 UTC

Description of problem:

During SmartState Analysis of RHOS VM, received multiple messages about failing to create snapshot

Version-Release number of selected component (if applicable):

5.4.0.0.23.20150423131011_69b48fd

How reproducible:

Unsure

Steps to Reproduce:
1. Perform SmartState Analysis on RHOS VM
2.
3.

Actual results:

Errors in evm.log

Expected results:

No errors, successful SmartState Analysis

Additional info:

evm.log excerpt:
[----] E, [2015-04-28T15:59:20.575060 #2618:eb1ea0] ERROR -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) MIQ(MiqOpenStackInstance#create_evm_snapshot) instance_id=[85a986f2-59f2-4f72-bcf8-8f8bd
[----] D, [2015-04-28T15:59:20.575191 #2618:eb1ea0] DEBUG -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) /var/www/miq/lib/OpenStackExtract/MiqOpenStackVm/MiqOpenStackInstance.rb:30:in `snapshot
/var/www/miq/lib/OpenStackExtract/MiqOpenStackVm/MiqOpenStackInstance.rb:34:in `snapshot_image_id'
/var/www/miq/lib/OpenStackExtract/MiqOpenStackVm/MiqOpenStackInstance.rb:47:in `create_evm_snapshot'
/var/www/miq/vmdb/app/models/ems_openstack.rb:76:in `vm_create_evm_snapshot'
/var/www/miq/vmdb/app/models/vm_scan.rb:56:in `call_snapshot_create'
/var/www/miq/vmdb/app/models/job/state_machine.rb:29:in `signal'
/var/www/miq/vmdb/app/models/miq_queue.rb:356:in `block in deliver'
/opt/rh/ruby200/root/usr/share/ruby/timeout.rb:66:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:352:in `deliver'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:107:in `deliver_queue_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:135:in `deliver_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:152:in `block in do_work'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `loop'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `do_work'
/var/www/miq/vmdb/lib/workers/worker_base.rb:323:in `block in do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:141:in `run'
/var/www/miq/vmdb/lib/workers/worker_base.rb:122:in `start'
/var/www/miq/vmdb/lib/workers/worker_base.rb:23:in `start_worker'
/var/www/miq/vmdb/lib/workers/bin/worker.rb:3:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `eval'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `require'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `<top (required)>'
script/rails:6:in `require'
script/rails:6:in `<main>'
[----] E, [2015-04-28T15:59:20.575322 #2618:eb1ea0] ERROR -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) MIQ(EmsOpenstack#vm_create_evm_snapshot) vm=[test_instance_pwrctl_la9wABIa], error: unde
[----] D, [2015-04-28T15:59:20.575396 #2618:eb1ea0] DEBUG -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) /var/www/miq/lib/OpenStackExtract/MiqOpenStackVm/MiqOpenStackInstance.rb:30:in `snapshot
/var/www/miq/lib/OpenStackExtract/MiqOpenStackVm/MiqOpenStackInstance.rb:34:in `snapshot_image_id'
/var/www/miq/lib/OpenStackExtract/MiqOpenStackVm/MiqOpenStackInstance.rb:47:in `create_evm_snapshot'
/var/www/miq/vmdb/app/models/ems_openstack.rb:76:in `vm_create_evm_snapshot'
/var/www/miq/vmdb/app/models/vm_scan.rb:56:in `call_snapshot_create'
/var/www/miq/vmdb/app/models/job/state_machine.rb:29:in `signal'
/var/www/miq/vmdb/app/models/miq_queue.rb:356:in `block in deliver'
/opt/rh/ruby200/root/usr/share/ruby/timeout.rb:66:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:352:in `deliver'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:107:in `deliver_queue_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:135:in `deliver_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:152:in `block in do_work'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `loop'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `do_work'
/var/www/miq/vmdb/lib/workers/worker_base.rb:323:in `block in do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:141:in `run'
/var/www/miq/vmdb/lib/workers/worker_base.rb:122:in `start'
/var/www/miq/vmdb/lib/workers/worker_base.rb:23:in `start_worker'
/var/www/miq/vmdb/lib/workers/bin/worker.rb:3:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `eval'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `require'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `<top (required)>'
script/rails:6:in `require'
script/rails:6:in `<main>'
[----] E, [2015-04-28T15:59:20.575640 #2618:eb1ea0] ERROR -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) MIQ(scan-call_snapshot_create Failed to create evm snapshot with EMS. Error: [NoMethodEr
[----] I, [2015-04-28T15:59:20.606311 #2618:eb1ea0]  INFO -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) MIQ(Event.raise_evm_event): Event Raised [vm_scan_abort]
[----] I, [2015-04-28T15:59:20.627290 #2618:eb1ea0]  INFO -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) MIQ(Event.raise_evm_event): Alert for Event [vm_scan_abort]
[----] I, [2015-04-28T15:59:20.627580 #2618:eb1ea0]  INFO -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) MIQ(MiqAlert.evaluate_alerts) [vm_scan_abort] Target: VmOpenstack Name: [test_instance_p
[----] E, [2015-04-28T15:59:20.636632 #2618:eb1ea0] ERROR -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) action-abort: job aborting, Failed to create evm snapshot with EMS. Error: [NoMethodErro
[----] I, [2015-04-28T15:59:20.657978 #2618:eb1ea0]  INFO -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) action-finished: job finished, Failed to create evm snapshot with EMS. Error: [NoMethodE
[----] I, [2015-04-28T15:59:20.666449 #2618:eb1ea0]  INFO -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) dispatch_finish: Dispatch Status is 'finished'
[----] I, [2015-04-28T15:59:20.691268 #2618:eb1ea0]  INFO -- : Q-task_id([d2df267c-ede0-11e4-b9c9-001a4a60db13]) MIQ(MiqQueue.delivered)  Message id: [3642], State: [ok], Delivered in [1.798055503] sec

VM is available with logfiles

Comment 2 Jerry Keselman 2015-04-30 18:25:44 UTC

Thom, do you have the actual logfiles? The snippet pasted into the bz has some end-of-line truncating that may be useful information.

Also a pointer to your test environment would be helpful if possible.

Thanks.

Comment 3 Thom Carlin 2015-04-30 18:37:43 UTC

Supplied via IRC

Comment 4 Jerry Keselman 2015-05-04 15:56:37 UTC

I did see this message for this particular VM last week on Thursday but some time between then and today the VM in question was deleted from the OpenStack provider.  None of the other VMs we have are exhibiting this issue and we cannot recreate it for new VMs.  It is possible that the initial cause of this was environmental in nature although the code should handle the situation.  I would like to remove this from the "blocker" list and keep this open to try to debug as a lower priority issue.

Comment 6 Thom Carlin 2015-05-05 11:55:56 UTC

Agreed, did not reoccur on RHOS6.

Comment 7 Thom Carlin 2015-05-07 17:16:47 UTC

Reoccured on RHOS6

Comment 9 John Prause 2016-03-14 15:53:03 UTC

Deferring to 5.5.4 since today is dev complete for 5.5.3

Comment 10 Jerry Keselman 2016-04-19 15:18:59 UTC

Changing the needing to Thom Carlin.

Comment 11 Thom Carlin 2016-04-19 15:20:56 UTC

Changing back to dajo.

Comment 13 Jerry Keselman 2016-04-21 14:47:29 UTC

Closing.