Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1421619

Summary:	Command proceed to perform the next execution phase although execute() failed
Product:	[oVirt] ovirt-engine	Reporter:	Liron Aravot <laravot>
Component:	Backend.Core	Assignee:	Liron Aravot <laravot>
Status:	CLOSED CURRENTRELEASE	QA Contact:	Kevin Alon Goldblatt <kgoldbla>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	4.1.0	CC:	amureini, bugs, gklein, laravot, ratamir
Target Milestone:	ovirt-4.1.1	Keywords:	CodeChange
Target Release:	4.1.1.2	Flags:	rule-engine: ovirt-4.1+
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2017-04-21 09:33:27 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	Storage	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Liron Aravot 2017-02-13 09:29:26 UTC

Description of problem:
Command which is using the SerialChildCommandsExecutionCallback and fails during its execute() will proceed to perform the next operation.

Comment 1 Red Hat Bugzilla Rules Engine 2017-02-13 09:32:03 UTC

Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.

Comment 2 Raz Tamir 2017-02-16 14:46:16 UTC

Liron,
can you provide steps to verify this?

Comment 3 Liron Aravot 2017-02-22 11:05:10 UTC

1. Create a VM with 1 disk
2. Create a template from that VM (with the disk on NFS domain)
3. Delete the template disk manually from the storage.
4. Add "Server" VM based on that template

Look for similar message to:
 [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler8) [62c5f460] Command 'CopyImageGroupWithData' id: 'be0f838f-0785-44a9-8847-52a732084ee7' execution didn't complete, not proceeding to perform the next operatio

Comment 4 Kevin Alon Goldblatt 2017-03-09 21:10:40 UTC

Verified with the following code:
--------------------------------------------------------
ovirt-engine-4.1.1.3-0.1.el7.noarc
rhevm-4.1.1.3-0.1.el7.noarch
vdsm-4.19.7-1.el7ev.x86_64

Verified with the following scenario:
--------------------------------------------------------
1. Create a VM with 1 disk
2. Create a template from that VM (with the disk on NFS domain)
3. Delete the template disk manually from the storage.
4. Add "Server" VM based on that template

Add VM based on template fails - does no move on to next step

Moving to VERIFIED!

Engine.log
-----------------------
2017-03-09 23:04:43,121+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler8) [7eb50eff] Failed in 'HSMGetAllTasksStatusesVDS' method
2017-03-09 23:04:43,156+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler8) [7eb50eff] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VDSM purple-vds2.qa.lab.tlv.redhat.com command HSMGetAllTasksStatusesVDS failed: Image path does not exist or cannot be accessed/created
2017-03-09 23:04:43,156+02 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler8) [7eb50eff] SPMAsyncTask::PollTask: Polling task 'd69491a2-c356-4761-bf99-023d415c8bff' (Parent Command 'CreateSnapshotFromTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'.
2017-03-09 23:04:43,164+02 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler8) [7eb50eff] BaseAsyncTask::logEndTaskFailure: Task 'd69491a2-c356-4761-bf99-023d415c8bff' (Parent Command 'CreateSnapshotFromTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure:
-- Result: 'cleanSuccess'
-- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Image path does not exist or cannot be accessed/created, code = 254',
-- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Image path does not exist or cannot be accessed/created, code = 254'
2017-03-09 23:04:43,165+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler8) [7eb50eff] CommandAsyncTask::endActionIfNecessary: All tasks of command 'ecc1a374-b289-470c-816b-5dc34f514855' has ended -> executing 'endAction'
2017-03-09 23:04:43,165+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler8) [7eb50eff] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'ecc1a374-b289-470c-816b-5dc34f514855'): calling endAction '.
2017-03-09 23:04:43,166+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-14) [7eb50eff] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'CreateSnapshotFromTemplate',
2017-03-09 23:04:43,180+02 INFO  [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] Command [id=ecc1a374-b289-470c-816b-5dc34f514855]: Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands.
2017-03-09 23:04:43,181+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshotFromTemplate' completed, handling the result.
2017-03-09 23:04:43,181+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshotFromTemplate' succeeded, clearing tasks.
2017-03-09 23:04:43,181+02 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'd69491a2-c356-4761-bf99-023d415c8bff'
2017-03-09 23:04:43,185+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{runAsync='true', storagePoolId='00000001-0001-0001-0001-000000000311', ignoreFailoverLimit='false', taskId='d69491a2-c356-4761-bf99-023d415c8bff'}), log id: 8ed0ee6
2017-03-09 23:04:43,187+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] START, HSMClearTaskVDSCommand(HostName = purple-vds2.qa.lab.tlv.redhat.com, HSMTaskGuidBaseVDSCommandParameters:{runAsync='true', hostId='c82979b9-9c8c-4f66-92f8-2172ec54f99e', taskId='d69491a2-c356-4761-bf99-023d415c8bff'}), log id: 7090902e
2017-03-09 23:04:44,207+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] FINISH, HSMClearTaskVDSCommand, log id: 7090902e
2017-03-09 23:04:44,207+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] FINISH, SPMClearTaskVDSCommand, log id: 8ed0ee6
2017-03-09 23:04:44,252+02 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] BaseAsyncTask::removeTaskFromDB: Removed task 'd69491a2-c356-4761-bf99-023d415c8bff' from DataBase
2017-03-09 23:04:44,252+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-14) [3a25ba09] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'ecc1a374-b289-470c-816b-5dc34f514855'
2017-03-09 23:04:44,563+02 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler9) [3a25ba09] Command 'AddVm' id: '35f23bce-942d-4c0a-b082-013b690701ad' child commands '[ecc1a374-b289-470c-816b-5dc34f514855]' executions were completed, status 'FAILED'
2017-03-09 23:04:45,646+02 ERROR [org.ovirt.engine.core.bll.AddVmCommand] (DefaultQuartzScheduler1) [3a25ba09] Ending command 'org.ovirt.engine.core.bll.AddVmCommand' with failure.
2017-03-09 23:04:45,665+02 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (DefaultQuartzScheduler1) [3a25ba09] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' with failure.
2017-03-09 23:04:45,942+02 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (DefaultQuartzScheduler1) [] Lock freed to object 'EngineLock:{exclusiveLocks='[server=<VM_NAME, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='[b6b9b11e-c640-430c-b515-11b3a26e7504=<TEMPLATE, ACTION_TYPE_FAILED_TEMPLATE_IS_USED_FOR_CREATE_VM$VmName server>, bd9b7a6e-8c3e-4748-bbb9-e42902e5b0a9=<DISK, ACTION_TYPE_FAILED_DISK_IS_USED_FOR_CREATE_VM$VmName server>]'}'
2017-03-09 23:04:46,023+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Correlation ID: 5b64de1e-725a-4383-a22d-0113eae6de3e, Job ID: f820488e-c353-4fc5-9551-41865ad2a8a6, Call Stack: null, Custom Event ID: -1, Message: Failed to complete VM server creation.
2017-03-09 23:06:15,595+02 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler1) [] Setting new tasks map. The map contains now 0 tasks
2017-03-09 23:06:15,596+02 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler1) [] Cleared all tasks of pool '00000001-0001-0001-0001-000000000311'.
~