Bug 1168620 - PPC - Live Storage Migration fails on FC Storage
Summary: PPC - Live Storage Migration fails on FC Storage
Keywords:
Status: CLOSED INSUFFICIENT_DATA
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine
Version: 3.4.4
Hardware: ppc64
OS: Unspecified
unspecified
urgent
Target Milestone: ovirt-3.6.3
: 3.6.0
Assignee: Adam Litke
QA Contact: Aharon Canan
URL:
Whiteboard: storage
Depends On: 1102881
Blocks: 1122979 1184995
TreeView+ depends on / blocked
 
Reported: 2014-11-27 12:31 UTC by Kevin Alon Goldblatt
Modified: 2016-03-10 06:25 UTC (History)
20 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-06-04 15:55:40 UTC
oVirt Team: Storage
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
engine vdsm and server logs (1.53 MB, application/x-gzip)
2014-11-27 12:31 UTC, Kevin Alon Goldblatt
no flags Details
New logs including libvirt from hosts 03 and 04 (3.00 MB, application/x-gzip)
2014-11-30 07:51 UTC, Kevin Alon Goldblatt
no flags Details
Added new logs for need-info (1.35 MB, application/x-gzip)
2014-12-16 15:25 UTC, Kevin Alon Goldblatt
no flags Details
Added new logs for need-info (971.98 KB, application/x-gzip)
2015-01-15 18:07 UTC, Kevin Alon Goldblatt
no flags Details
Engine and vdsm logs (808.05 KB, application/x-gzip)
2015-02-24 14:55 UTC, Kevin Alon Goldblatt
no flags Details
server, engine and vdsm logs (1.51 MB, application/x-gzip)
2015-03-18 15:59 UTC, Kevin Alon Goldblatt
no flags Details
server, engine and vdsm logs (2.30 MB, application/x-gzip)
2015-03-18 16:13 UTC, Kevin Alon Goldblatt
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1102881 0 unspecified CLOSED virDomainBlockCommit fails with live snapshots on oVirt block storage 2021-02-22 00:41:40 UTC

Internal Links: 1102881

Description Kevin Alon Goldblatt 2014-11-27 12:31:10 UTC
Created attachment 962002 [details]
engine vdsm and server logs

Description of problem:
Live Storage Migration fails on FC storage

Version-Release number of selected component (if applicable):
rhevm-3.4.4-2.2.el6ev.noarch
vdsm-4.14.18-0.pkvm2_1_1.ppc64

How reproducible:
always

Steps to Reproduce:
1. Create 2 FC Storage Domains (kev1 and kev2)
1. Create VM with 2 disks (one 7G thin and one 9g preallocated) on kev1
2. Start the VM
3. From the VM - Disks tab select the 2 disks and perform a Live Storage Migration from kev1 to kev2 The operation fails with "Failed to change disk image"

Actual results:
The Live Storage Migration fails

Expected results:
Live Storage Migration should work

Additional info:
ENGINE LOG...................................................

2014-11-27 11:32:29,129 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand] (ajp-/127.0.0.1:8702-3) [42e67925] Lock Acquired to object EngineLock [exclusiveLocks= key: e1dc0f56-0760-4fd7-a349-8274211e2ef5 value: DISK
2014-11-27 11:32:29,323 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand] (org.ovirt.thread.pool-4-thread-33) [42e67925] Running command: LiveMigrateVmDisksCommand Task handler: LiveSnapshotTaskHandler internal: false. Entities affected :  ID: 3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage,  ID: e1dc0f56-0760-4fd7-a349-8274211e2ef5 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:32:30,311 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-4-thread-33) [17d0286e] Adding task a6c2f1dd-3b67-400b-ab2f-3d80190553a1 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-11-27 11:32:31,103 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-4-thread-33) [144c978b] Adding task bf7dd915-1a6a-4aa5-9630-1498c2dadc76 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-11-27 11:32:31,346 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-4-thread-33) Correlation ID: 755a587e, Job ID: 4d073b70-b6e0-445f-9faf-6d537aa74c3c, Call Stack: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'kevin_vm_1' was initiated by admin.
2014-11-27 11:32:41,080 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-18) [18ad7839] SPMAsyncTask::PollTask: Polling task a6c2f1dd-3b67-400b-ab2f-3d80190553a1 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2014-11-27 11:32:41,127 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-18) [18ad7839] BaseAsyncTask::OnTaskEndSuccess: Task a6c2f1dd-3b67-400b-ab2f-3d80190553a1 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:32:41,128 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-18) [18ad7839] SPMAsyncTask::PollTask: Polling task bf7dd915-1a6a-4aa5-9630-1498c2dadc76 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2014-11-27 11:32:41,187 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-18) [18ad7839] BaseAsyncTask::OnTaskEndSuccess: Task bf7dd915-1a6a-4aa5-9630-1498c2dadc76 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:32:41,187 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-44) [18ad7839] CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateVmDisks, executionIndex: 0
2014-11-27 11:32:41,280 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand] (org.ovirt.thread.pool-4-thread-44) [18ad7839] Ending command successfully: org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand
2014-11-27 11:32:54,190 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-4-thread-44) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'kevin_vm_1' has been completed.
2014-11-27 11:32:54,247 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand] (org.ovirt.thread.pool-4-thread-44) Running command: LiveMigrateVmDisksCommand Task handler: LiveMigrateDisksTaskHandler internal: false. Entities affected :  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:32:54,514 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-44) [717a4058] Lock Acquired to object EngineLock [exclusiveLocks= , sharedLocks= key: 5acd6f4f-162c-4f7f-976b-28eedebbe6d2 value: VM
2014-11-27 11:32:54,587 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-44) [717a4058] Running command: LiveMigrateDiskCommand Task handler: CreateImagePlaceholderTaskHandler internal: true. Entities affected :  ID: 3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:32:55,263 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-4-thread-44) [717a4058] Adding task b0461f70-52ec-45b7-b212-26bb55c1434f (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-11-27 11:32:55,609 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-44) [72d2281] Lock Acquired to object EngineLock [exclusiveLocks= , sharedLocks= key: 5acd6f4f-162c-4f7f-976b-28eedebbe6d2 value: VM
2014-11-27 11:32:55,662 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-44) [72d2281] Running command: LiveMigrateDiskCommand Task handler: CreateImagePlaceholderTaskHandler internal: true. Entities affected :  ID: e1dc0f56-0760-4fd7-a349-8274211e2ef5 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:32:56,065 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-4-thread-44) [72d2281] Adding task 0d2b7a79-fb38-4ab1-9634-fb0739c8859d (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-11-27 11:32:56,128 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand] (org.ovirt.thread.pool-4-thread-44) [72d2281] Lock freed to object EngineLock [exclusiveLocks= key: e1dc0f56-0760-4fd7-a349-8274211e2ef5 value: DISK
2014-11-27 11:32:56,129 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-44) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateVmDisks completed, handling the result.
2014-11-27 11:32:56,129 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-44) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateVmDisks succeeded, clearing tasks.
2014-11-27 11:33:01,420 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-41) [75b07d0a] SPMAsyncTask::PollTask: Polling task 0d2b7a79-fb38-4ab1-9634-fb0739c8859d (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2014-11-27 11:33:01,518 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-41) [75b07d0a] BaseAsyncTask::OnTaskEndSuccess: Task 0d2b7a79-fb38-4ab1-9634-fb0739c8859d (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:33:01,519 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-41) [75b07d0a] SPMAsyncTask::PollTask: Polling task b0461f70-52ec-45b7-b212-26bb55c1434f (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2014-11-27 11:33:01,519 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-23) [75b07d0a] CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateDisk, executionIndex: 0
2014-11-27 11:33:01,592 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-23) [72d2281] Ending command successfully: org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand
2014-11-27 11:33:01,592 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-23) [72d2281] Running command: LiveMigrateDiskCommand Task handler: VmReplicateDiskStartTaskHandler internal: false. Entities affected :  ID: e1dc0f56-0760-4fd7-a349-8274211e2ef5 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:33:01,805 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-41) [75b07d0a] BaseAsyncTask::OnTaskEndSuccess: Task b0461f70-52ec-45b7-b212-26bb55c1434f (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:33:01,806 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-41) [75b07d0a] CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateDisk, executionIndex: 0
2014-11-27 11:33:01,948 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-41) [717a4058] Ending command successfully: org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand
2014-11-27 11:33:01,948 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-41) [717a4058] Running command: LiveMigrateDiskCommand Task handler: VmReplicateDiskStartTaskHandler internal: false. Entities affected :  ID: 3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:33:03,084 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-4-thread-23) [72d2281] Adding task 5ef7fa80-db21-4b31-9310-f3907e6b26eb (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-11-27 11:33:03,117 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-23) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk completed, handling the result.
2014-11-27 11:33:03,118 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-23) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk succeeded, clearing tasks.
2014-11-27 11:33:03,376 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-4-thread-41) [717a4058] Adding task d37592d5-5b16-4255-a271-37f35f041655 (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-11-27 11:33:03,393 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-41) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk completed, handling the result.
2014-11-27 11:33:03,393 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-41) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk succeeded, clearing tasks.
2014-11-27 11:33:12,171 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-50) [b4aec1d] SPMAsyncTask::PollTask: Polling task 5ef7fa80-db21-4b31-9310-f3907e6b26eb (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status running.
2014-11-27 11:33:12,171 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-50) [b4aec1d] SPMAsyncTask::PollTask: Polling task d37592d5-5b16-4255-a271-37f35f041655 (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status running.
2014-11-27 11:33:42,820 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-87) [6b4c5070] SPMAsyncTask::PollTask: Polling task d37592d5-5b16-4255-a271-37f35f041655 (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2014-11-27 11:33:42,887 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-87) [6b4c5070] BaseAsyncTask::OnTaskEndSuccess: Task d37592d5-5b16-4255-a271-37f35f041655 (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:33:42,887 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-35) [6b4c5070] CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateDisk, executionIndex: 1
2014-11-27 11:33:42,913 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-35) [717a4058] Ending command successfully: org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand
2014-11-27 11:33:42,913 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-35) [717a4058] Running command: LiveMigrateDiskCommand Task handler: VmReplicateDiskFinishTaskHandler internal: false. Entities affected :  ID: 3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:33:53,974 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-35) [717a4058] Command org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to VmReplicateDiskFinishVDS, error = Failed to change disk image (Failed with error FAILED_CHANGE_CD_IS_MOUNTED and code 41)
2014-11-27 11:33:53,977 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-35) [717a4058] Reverting task unknown, handler: org.ovirt.engine.core.bll.lsm.VmReplicateDiskStartTaskHandler
2014-11-27 11:33:54,333 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-35) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk completed, handling the result.
2014-11-27 11:33:54,333 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-35) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk hasnt succeeded, not clearing tasks, will attempt again next polling.
2014-11-27 11:34:03,431 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-42) [2930fea3] BaseAsyncTask::OnTaskEndSuccess: Task d37592d5-5b16-4255-a271-37f35f041655 (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:34:03,432 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-49) [2930fea3] CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateDisk, executionIndex: 0
2014-11-27 11:34:03,457 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-49) [717a4058] Ending command with failure: org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand
2014-11-27 11:34:03,489 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-49) [717a4058] Lock freed to object EngineLock [exclusiveLocks= , sharedLocks= key: 5acd6f4f-162c-4f7f-976b-28eedebbe6d2 value: VM
2014-11-27 11:34:03,538 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-49) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk completed, handling the result.
2014-11-27 11:34:03,538 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-49) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk succeeded, clearing tasks.
2014-11-27 11:34:13,694 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-16) [7a15bc72] SPMAsyncTask::PollTask: Polling task 5ef7fa80-db21-4b31-9310-f3907e6b26eb (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2014-11-27 11:34:13,738 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-16) [7a15bc72] BaseAsyncTask::OnTaskEndSuccess: Task 5ef7fa80-db21-4b31-9310-f3907e6b26eb (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:34:13,739 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-14) [7a15bc72] CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateDisk, executionIndex: 1
2014-11-27 11:34:13,764 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-14) [72d2281] Ending command successfully: org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand
2014-11-27 11:34:13,764 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-14) [72d2281] Running command: LiveMigrateDiskCommand Task handler: VmReplicateDiskFinishTaskHandler internal: false. Entities affected :  ID: e1dc0f56-0760-4fd7-a349-8274211e2ef5 Type: Disk,  ID: 69d2dc44-be61-4e1a-89f0-7b130755edd1 Type: Storage
2014-11-27 11:34:24,791 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-14) [72d2281] Command org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to VmReplicateDiskFinishVDS, error = Failed to change disk image (Failed with error FAILED_CHANGE_CD_IS_MOUNTED and code 41)
2014-11-27 11:34:24,807 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-14) [72d2281] Reverting task unknown, handler: org.ovirt.engine.core.bll.lsm.VmReplicateDiskStartTaskHandler
2014-11-27 11:34:25,386 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-14) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk completed, handling the result.
2014-11-27 11:34:25,386 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-14) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk hasnt succeeded, not clearing tasks, will attempt again next polling.
2014-11-27 11:34:33,996 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-37) [b543a03] BaseAsyncTask::OnTaskEndSuccess: Task 5ef7fa80-db21-4b31-9310-f3907e6b26eb (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-11-27 11:34:33,997 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-19) [b543a03] CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateDisk, executionIndex: 0
2014-11-27 11:34:34,083 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-19) [72d2281] Ending command with failure: org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand
2014-11-27 11:34:34,104 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-4-thread-19) [72d2281] Lock freed to object EngineLock [exclusiveLocks= , sharedLocks= key: 5acd6f4f-162c-4f7f-976b-28eedebbe6d2 value: VM
2014-11-27 11:34:34,138 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-19) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk completed, handling the result.
2014-11-27 11:34:34,138 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-19) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk succeeded, clearing tasks.

Comment 1 Allon Mureinik 2014-11-27 16:30:40 UTC
Does this only reproduce on FC?
Also, can you please attach libvirt logs? The failure seems to originate there.

Comment 2 Kevin Alon Goldblatt 2014-11-30 07:51:38 UTC
Created attachment 962866 [details]
New logs including libvirt from hosts 03 and 04

Comment 3 Adam Litke 2014-12-01 18:26:01 UTC
2014-11-27 10:33:33.636+0000: 101964: debug : qemuMonitorIOProcess:399 : QEMU_MONITOR_IO_PROCESS: mon=0x3fff80008dc0 buf={"id": "libvirt-407", "error": {"class": "GenericError", "desc": "Could not open backing file: Could not open '/rhev/data-center/d8392caf-eba2-47b2-95c7-ebbdfbc075ee/69d2dc44-be61-4e1a-89f0-7b130755edd1/images/3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525/../3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525/4f685f06-daf8-42f4-907a-a3e62e4fc896': Operation not permitted"}}^M
 len=354

The above line from the libvirtd log suggests that this is a SELinux issue (possibly related to Bug 1102881).

Please try to reproduce this with SELinux in permissive mode on the hosts (setenforce 0).

Comment 4 Michal Skrivanek 2014-12-02 10:47:40 UTC
I would also tried the workaround mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1102881#c34

Comment 5 Michal Skrivanek 2014-12-02 10:48:55 UTC
(In reply to Michal Skrivanek from comment #4)
I mean the behavior and error mentioned there...

Comment 6 Kevin Alon Goldblatt 2014-12-03 08:40:47 UTC
(In reply to Adam Litke from comment #3)
> 2014-11-27 10:33:33.636+0000: 101964: debug : qemuMonitorIOProcess:399 :
> QEMU_MONITOR_IO_PROCESS: mon=0x3fff80008dc0 buf={"id": "libvirt-407",
> "error": {"class": "GenericError", "desc": "Could not open backing file:
> Could not open
> '/rhev/data-center/d8392caf-eba2-47b2-95c7-ebbdfbc075ee/69d2dc44-be61-4e1a-
> 89f0-7b130755edd1/images/3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525/../3c1cb8cd-
> b5cd-4e7f-a36a-4ff6eb2aa525/4f685f06-daf8-42f4-907a-a3e62e4fc896': Operation
> not permitted"}}^M
>  len=354
> 
> The above line from the libvirtd log suggests that this is a SELinux issue
> (possibly related to Bug 1102881).
> 
> Please try to reproduce this with SELinux in permissive mode on the hosts
> (setenforce 0).

1. Please could you provde the steps to configure SELinux in permissive mode. 

2.Is this 'permissive mode' the default configuration on PPC Linux hosts? These are hosts that were installed and reside in Boston for the PPC test suite. We are time sharing them for the test effort. Will this configuration be expected from users of PPC with vdsm?

Comment 7 Adam Litke 2014-12-03 14:12:22 UTC
(In reply to Kevin Alon Goldblatt from comment #6)
> (In reply to Adam Litke from comment #3)
> > 2014-11-27 10:33:33.636+0000: 101964: debug : qemuMonitorIOProcess:399 :
> > QEMU_MONITOR_IO_PROCESS: mon=0x3fff80008dc0 buf={"id": "libvirt-407",
> > "error": {"class": "GenericError", "desc": "Could not open backing file:
> > Could not open
> > '/rhev/data-center/d8392caf-eba2-47b2-95c7-ebbdfbc075ee/69d2dc44-be61-4e1a-
> > 89f0-7b130755edd1/images/3c1cb8cd-b5cd-4e7f-a36a-4ff6eb2aa525/../3c1cb8cd-
> > b5cd-4e7f-a36a-4ff6eb2aa525/4f685f06-daf8-42f4-907a-a3e62e4fc896': Operation
> > not permitted"}}^M
> >  len=354
> > 
> > The above line from the libvirtd log suggests that this is a SELinux issue
> > (possibly related to Bug 1102881).
> > 
> > Please try to reproduce this with SELinux in permissive mode on the hosts
> > (setenforce 0).
> 
> 1. Please could you provde the steps to configure SELinux in permissive
> mode. 

To check the current mode, use the following command:
# sudo sestatus

To set permissive mode, enter the following command:
# sudo setenforce 0

To return the system to enforcing mode, use:
# sudo setenforce 1

> 2.Is this 'permissive mode' the default configuration on PPC Linux hosts?
> These are hosts that were installed and reside in Boston for the PPC test
> suite. We are time sharing them for the test effort. Will this configuration
> be expected from users of PPC with vdsm?

I am not sure what the current mode is since I do not have access to the systems.  I am asking you to do this check only for diagnostic purposes.  I do not intend for it to be a permanent workaround.

Comment 8 Aharon Canan 2014-12-04 15:16:33 UTC
Elad, 

Please try to check on your local setup with FC, we need to understand f it is related to PPC

Comment 9 Elad 2014-12-07 08:59:44 UTC
(In reply to Aharon Canan from comment #8)
> Elad, 
> 
> Please try to check on your local setup with FC, we need to understand f it
> is related to PPC

Checked the described scenario on a non-PPC environment. RHEL7 installed on the host, SElinux version selinux-policy-3.12.1-153.el7.noarch in enforcing mode. 
Didn't manage to reproduce.

Comment 10 Allon Mureinik 2014-12-07 09:42:09 UTC
Kevin/Elad, what selinux RPMs does the PPC env. have?
Could you please run 
$ rpm -qa | grep selinux

on both envs?

Thanks!

Comment 11 Kevin Alon Goldblatt 2014-12-07 10:13:52 UTC
For engine 10.34.63.61 PPC 
-------------------------------
[root@ls-rhevm32 ~]# rpm -qa | grep selinux
selinux-policy-targeted-3.7.19-260.el6.noarch
libselinux-2.0.94-5.8.el6.x86_64
libselinux-python-2.0.94-5.8.el6.x86_64
selinux-policy-3.7.19-260.el6.noarch
libselinux-utils-2.0.94-5.8.el6.x86_64


For PPC FC Host  ibm-p8-rhevm-03.rhts.eng.bos.redhat.com 
-----------------------------------------------------------
[root@ibm-p8-rhevm-03 ~]# rpm -qa | grep selinux
libselinux-ruby-2.1.13-15.pkvm2_1.5.ppc64
selinux-policy-devel-3.12.1-191.1.pkvm2_1_1.1.noarch
libselinux-python-2.1.13-15.pkvm2_1.5.ppc64
libselinux-2.1.13-15.pkvm2_1.5.ppc64
selinux-policy-3.12.1-191.1.pkvm2_1_1.1.noarch
libselinux-utils-2.1.13-15.pkvm2_1.5.ppc64
selinux-policy-targeted-3.12.1-191.1.pkvm2_1_1.1.noarch


For PPC FC host  ibm-p8-rhevm-04.rhts.eng.bos.redhat.com 
-----------------------------------------------------------
[root@ibm-p8-rhevm-04 ~]# rpm -qa | grep selinux
libselinux-ruby-2.1.13-15.pkvm2_1.5.ppc64
selinux-policy-devel-3.12.1-191.1.pkvm2_1_1.1.noarch
libselinux-python-2.1.13-15.pkvm2_1.5.ppc64
libselinux-2.1.13-15.pkvm2_1.5.ppc64
selinux-policy-3.12.1-191.1.pkvm2_1_1.1.noarch
libselinux-utils-2.1.13-15.pkvm2_1.5.ppc64
selinux-policy-targeted-3.12.1-191.1.pkvm2_1_1.1.noarch

Comment 13 Elad 2014-12-07 11:09:35 UTC
On the non-PPC:

[root@green-vdsa ~]# rpm -qa |grep  selinux
libselinux-2.2.2-6.el7.x86_64
libselinux-utils-2.2.2-6.el7.x86_64
libselinux-python-2.2.2-6.el7.x86_64
selinux-policy-3.12.1-153.el7.noarch
selinux-policy-targeted-3.12.1-153.el7.noarch

Comment 15 Michal Skrivanek 2014-12-10 13:47:39 UTC
result of testing in "permissive" mode as per comment #7?

Comment 16 Kevin Alon Goldblatt 2014-12-16 15:23:43 UTC
(In reply to Michal Skrivanek from comment #15)
> result of testing in "permissive" mode as per comment #7?

Reproduced this with SELinux in permissive mode on the hosts
(setenforce 0).

set permissive mode, enter the following command:
# sudo setenforce 0

Ran the same scenario again with the same outcome. Live storage migration failed

Attached new logs:

Comment 17 Kevin Alon Goldblatt 2014-12-16 15:25:09 UTC
Created attachment 969596 [details]
Added new logs for need-info

Added new logs for need-info

Comment 19 Tal Nisan 2015-01-12 12:46:32 UTC
Daniel, please have a look

Comment 20 Daniel Erez 2015-01-12 13:27:53 UTC
(In reply to Kevin Alon Goldblatt from comment #16)
> (In reply to Michal Skrivanek from comment #15)
> > result of testing in "permissive" mode as per comment #7?
> 
> Reproduced this with SELinux in permissive mode on the hosts
> (setenforce 0).
> 
> set permissive mode, enter the following command:
> # sudo setenforce 0
> 
> Ran the same scenario again with the same outcome. Live storage migration
> failed
> 
> Attached new logs:

Hi Kevin,

* Have you tested the scenario on new disks or the ones from previous test?
* Is it reproducible on iSCSI as well?

Comment 21 Kevin Alon Goldblatt 2015-01-15 17:54:10 UTC
(In reply to Daniel Erez from comment #20)
> (In reply to Kevin Alon Goldblatt from comment #16)
> > (In reply to Michal Skrivanek from comment #15)
> > > result of testing in "permissive" mode as per comment #7?
> > 
> > Reproduced this with SELinux in permissive mode on the hosts
> > (setenforce 0).
> > 
> > set permissive mode, enter the following command:
> > # sudo setenforce 0
> > 
> > Ran the same scenario again with the same outcome. Live storage migration
> > failed
> > 
> > Attached new logs:
> 
> Hi Kevin,
> 
> * Have you tested the scenario on new disks or the ones from previous test?
> * Is it reproducible on iSCSI as well?

1. I reproduced it with new disks
That test was specifically FC

2. Ran a scenario with ISCI block domains and disks - Also failed 

Engine log
-----------------
2015-01-15 18:30:32,296 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-4-thread-29) Correlation ID: 5cbd23e, Job ID: 6779e5c5-acfd-4817-bbe5-59998a0d7910, Call Stack: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'vm_scsi' was initiated by admin.
2015-01-15 18:30:32,315 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (org.ovirt.thread.pool-4-thread-29) BaseAsyncTask::startPollingTask: Starting to poll task 7dbf316b-a637-46a8-baed-404474f350bc.
2015-01-15 18:30:32,315 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (org.ovirt.thread.pool-4-thread-29) BaseAsyncTask::startPollingTask: Starting to poll task 7a19fa00-96c7-439e-80ec-1a0d30d7b2a6.
2015-01-15 18:30:40,450 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (DefaultQuartzScheduler_Worker-91) Polling and updating Async Tasks: 2 tasks, 2 tasks to poll now
2015-01-15 18:30:40,665 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-91) SPMAsyncTask::PollTask: Polling task 7dbf316b-a637-46a8-baed-404474f350bc (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2015-01-15 18:30:40,712 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-91) BaseAsyncTask::OnTaskEndSuccess: Task 7dbf316b-a637-46a8-baed-404474f350bc (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2015-01-15 18:30:40,712 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (DefaultQuartzScheduler_Worker-91) Task with DB Task ID 5bbdc020-439e-4c7c-9b0d-91edbc4bf301 and VDSM Task ID 7a19fa00-96c7-439e-80ec-1a0d30d7b2a6 is in state Polling. End action for command 9ddd17aa-8892-4071-8683-c240bd25664d will proceed when all the entitys tasks are completed.
2015-01-15 18:30:40,712 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-91) SPMAsyncTask::PollTask: Polling task 7a19fa00-96c7-439e-80ec-1a0d30d7b2a6 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status running.
2015-01-15 18:30:40,713 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (DefaultQuartzScheduler_Worker-91) Finished polling Tasks, will poll again in 10 seconds.
2015-01-15 18:30:49,174 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-3) Running command: LoginUserCommand internal: false.
2015-01-15 18:30:49,221 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-3) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User admin logged in.
2015-01-15 18:30:50,974 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-47) BaseAsyncTask::OnTaskEndSuccess: Task 7dbf316b-a637-46a8-baed-404474f350bc (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2015-01-15 18:30:50,974 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (DefaultQuartzScheduler_Worker-47) Task with DB Task ID 5bbdc020-439e-4c7c-9b0d-91edbc4bf301 and VDSM Task ID 7a19fa00-96c7-439e-80ec-1a0d30d7b2a6 is in state Polling. End action for command 9ddd17aa-8892-4071-8683-c240bd25664d will proceed when all the entitys tasks are completed.
2015-01-15 18:30:50,974 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-47) SPMAsyncTask::PollTask: Polling task 7a19fa00-96c7-439e-80ec-1a0d30d7b2a6 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2015-01-15 18:30:50,991 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-47) BaseAsyncTask::OnTaskEndSuccess: Task 7a19fa00-96c7-439e-80ec-1a0d30d7b2a6 (Parent Command LiveMigrateVmDisks, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2015-01-15 18:30:50,991 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (DefaultQuartzScheduler_Worker-47) CommandAsyncTask::EndActionIfNecessary: All tasks of command 9ddd17aa-8892-4071-8683-c240bd25664d has ended -> executing endAction
2015-01-15 18:30:50,992 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (DefaultQuartzScheduler_Worker-47) CommandAsyncTask::endAction: Ending action for 2 tasks (command ID: 9ddd17aa-8892-4071-8683-c240bd25664d): calling endAction .
2015-01-15 18:30:50,992 INFO  [org.ovirt.engine.core.bll.CommandAsyncTask] (org.ovirt.thread.pool-4-thread-23) CommandAsyncTask::EndCommandAction [within thread] context: Attempting to endAction LiveMigrateVmDisks, executionIndex: 0
2015-01-15 18:30:51,035 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand] (org.ovirt.thread.pool-4-thread-23) Ending command successfully: org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand
2015-01-15 18:30:51,042 INFO  [org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand] (org.ovirt.thread.pool-4-thread-23) Ending command successfully: org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand
2015-01-15 18:30:51,080 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (org.ovirt.thread.pool-4-thread-23) START, SnapshotVDSCommand(HostName = rhevm3, HostId = fa85bf7a-4658-4f9d-ab09-c751964cfdde, vmId=08789f3f-be6f-4e86-866d-5e683dd84b0c), log id: 33bf3526
2015-01-15 18:30:54,977 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8702-8) Running command: LoginUserCommand internal: false.
2015-01-15 18:30:55,116 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-8) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User admin logged in.
2015-01-15 18:31:02,385 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (org.ovirt.thread.pool-4-thread-23) Failed in SnapshotVDS method
2015-01-15 18:31:02,386 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (org.ovirt.thread.pool-4-thread-23) Command org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand return value 
 StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=48, mMessage=Snapshot failed]]
2015-01-15 18:31:02,386 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (org.ovirt.thread.pool-4-thread-23) HostName = rhevm3
2015-01-15 18:31:02,395 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (org.ovirt.thread.pool-4-thread-23) Command SnapshotVDSCommand(HostName = rhevm3, HostId = fa85bf7a-4658-4f9d-ab09-c751964cfdde, vmId=08789f3f-be6f-4e86-866d-5e683dd84b0c) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = Snapshot failed, code = 48
2015-01-15 18:31:02,395 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (org.ovirt.thread.pool-4-thread-23) FINISH, SnapshotVDSCommand, log id: 33bf3526
2015-01-15 18:31:02,396 WARN  [org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand] (org.ovirt.thread.pool-4-thread-23) Wasnt able to live snapshot due to error: VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = Snapshot failed, code = 48 (Failed with error SNAPSHOT_FAILED and code 48). VM will still be configured to the new created snapshot
2015-01-15 18:31:02,438 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-4-thread-23) Correlation ID: null, Call Stack: org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = Snapshot failed, code = 48 (Failed with error SNAPSHOT_FAILED and code 48)
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:116)
 at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.RunVdsCommand(VDSBrokerFrontendImpl.java:33)
        at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:1981)
        at org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand$2.runInTransaction(CreateAllSnapshotsFromVmCommand.java:354)
        at org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand$2.runInTransaction(CreateAllSnapshotsFromVmCommand.java:351)
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174)
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116)
        at org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand.performLiveSnapshot(CreateAllSnapshotsFromVmCommand.java:351)
        at org.ovirt.engine.core.bll.CreateAllSnapshotsFromVmCommand.endVmCommand(CreateAllSnapshotsFromVmCommand.java:273)
        at org.ovirt.engine.core.bll.VmCommand.endSuccessfully(VmCommand.java:304)
        at org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:614)
        at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:560)
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1896)
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:151)
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:118)
        at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:492)
        at org.ovirt.engine.core.bll.Backend.endAction(Backend.java:448)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374)
        at org.ovirt.engine.core.bll.interceptors.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:13)
        at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:89)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:250)
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:400)
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:242)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
        at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:185)
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
        at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73)
        at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view10.endAction(Unknown Source)
        at org.ovirt.engine.core.bll.lsm.LiveSnapshotTaskHandler.endCreateAllSnapshots(LiveSnapshotTaskHandler.java:101)
        at org.ovirt.engine.core.bll.lsm.LiveSnapshotTaskHandler.endSuccessfully(LiveSnapshotTaskHandler.java:76)
        at org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:607)
        at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:560)
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1896)
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:210)
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:149)
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:118)
        at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:492)
        at org.ovirt.engine.core.bll.lsm.LiveMigrateVmDisksCommand.endAction(LiveMigrateVmDisksCommand.java:85)
        at org.ovirt.engine.core.bll.Backend.endAction(Backend.java:448)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374)
        at org.ovirt.engine.core.bll.interceptors.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:13)
        at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374)
        at org.ovirt.engine.core.bll.interceptors.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:13)
        at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:89)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:259)
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:398)
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:242)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
        at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:185)
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
        at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73)
 at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view10.endAction(Unknown Source)
        at org.ovirt.engine.core.bll.CommandAsyncTask.EndCommandAction(CommandAsyncTask.java:147)
        at org.ovirt.engine.core.bll.CommandAsyncTask.access$000(CommandAsyncTask.java:25)
        at org.ovirt.engine.core.bll.CommandAsyncTask$1.run(CommandAsyncTask.java:106)
        at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:97)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
, Custom Event ID: -1, Message: Failed to create live snapshot 'Auto-generated for Live Storage Migration' for VM 'vm_scsi'. VM restart is recommended.

Comment 22 Kevin Alon Goldblatt 2015-01-15 18:07:58 UTC
Created attachment 980578 [details]
Added new logs for need-info

Comment 23 Daniel Erez 2015-01-15 18:39:32 UTC
Hi Kevin,

According to the attached log, there was an error in live snapshot phase.
Can you please try to live snapshot a disk with both PPC and x86 host in the same environment. Has live snapshot/live migrate been previously tested with PPC?

Comment 24 Adam Litke 2015-01-15 20:18:20 UTC
This seems like it could be related to https://bugzilla.redhat.com/show_bug.cgi?id=1091094 .  Even though these are block-based snapshots, we are creating them as file type.  In 3.4 we haven't yet seen any problems with this, but maybe this could be our first 3.4 issue because of this?

Thread-80::DEBUG::2014-12-16 13:49:09,567::vm::4066::vm.Vm::(snapshot) vmId=`c2f239c9-3f75-42fc-9a03-1b693f5fa23f`::<domainsnapshot>
        <disks>
                <disk name="vda" snapshot="external">
                        <source file="/rhev/data-center/4093a270-c2c7-42a8-bce3-beeb70874606/1121d792-8b90-4cc6-99bf-7ef32aa95b49/images/397dcb88-72e2-48f3-8078-8a28e1085a1a/54348c22-4297-4f6a-a5d5-49a27624f4c5"/>
                </disk>
                <disk name="sdb" snapshot="external">
                        <source file="/rhev/data-center/4093a270-c2c7-42a8-bce3-beeb70874606/1121d792-8b90-4cc6-99bf-7ef32aa95b49/images/3378ef50-5411-47c3-8197-e32662fa1947/04617edb-2ce1-4042-bddf-99c627fd77f0"/>
                </disk>
        </disks>
</domainsnapshot>

Comment 25 Allon Mureinik 2015-01-15 21:28:59 UTC
(In reply to Adam Litke from comment #24)
> This seems like it could be related to
> https://bugzilla.redhat.com/show_bug.cgi?id=1091094 .
In that case, wouldn't the backport done in bug 1175686 solve this? Perhaps it's worth retesting with 4.14.18-6?

Comment 26 Adam Litke 2015-01-15 22:03:19 UTC
Yes, that seems like a good idea.

Comment 27 Allon Mureinik 2015-01-15 22:12:52 UTC
(In reply to Allon Mureinik from comment #25)
> (In reply to Adam Litke from comment #24)
> > This seems like it could be related to
> > https://bugzilla.redhat.com/show_bug.cgi?id=1091094 .
> In that case, wouldn't the backport done in bug 1175686 solve this? Perhaps
> it's worth retesting with 4.14.18-6?
Michal, do we have such a build for PPC? I could not find it in brew.

Comment 29 Aharon Canan 2015-01-18 10:04:52 UTC
(In reply to Daniel Erez from comment #23)
> Hi Kevin,
> 
> According to the attached log, there was an error in live snapshot phase.
> Can you please try to live snapshot a disk with both PPC and x86 host in the
> same environment. Has live snapshot/live migrate been previously tested with
> PPC?

live snapshot tested with PPC but not on mixed setup.

Comment 30 Allon Mureinik 2015-01-18 10:42:36 UTC
(In reply to Aharon Canan from comment #29)
> (In reply to Daniel Erez from comment #23)
> > Hi Kevin,
> > 
> > According to the attached log, there was an error in live snapshot phase.
> > Can you please try to live snapshot a disk with both PPC and x86 host in the
> > same environment. Has live snapshot/live migrate been previously tested with
> > PPC?
> 
> live snapshot tested with PPC but not on mixed setup.
On what VDSM version?

Comment 32 Aharon Canan 2015-01-18 13:18:01 UTC
(In reply to Allon Mureinik from comment #30)
> (In reply to Aharon Canan from comment #29)
> > (In reply to Daniel Erez from comment #23)
> > > Hi Kevin,
> > > 
> > > According to the attached log, there was an error in live snapshot phase.
> > > Can you please try to live snapshot a disk with both PPC and x86 host in the
> > > same environment. Has live snapshot/live migrate been previously tested with
> > > PPC?
> > 
> > live snapshot tested with PPC but not on mixed setup.
> On what VDSM version?

vdsm-4.14.18-0.pkvm2_1_1.ppc64

Comment 36 Eyal Edri 2015-01-22 08:55:35 UTC
3.4.5 build has shipped, no respins are planned.
moving to 3.4.6 as candidate

Comment 37 Kevin Alon Goldblatt 2015-02-24 13:32:15 UTC
I ran the same scenario as above with the fixes Adam provided. The Live Merge operation still fails.

Comment 38 Allon Mureinik 2015-02-24 13:34:00 UTC
(In reply to Kevin Alon Goldblatt from comment #37)
> I ran the same scenario as above with the fixes Adam provided. The Live
> Merge operation still fails.
There is no live MERGE in 3.4.z.
Did you mean live storage MIGRATION?

Comment 39 Kevin Alon Goldblatt 2015-02-24 14:55:04 UTC
Created attachment 994737 [details]
Engine and vdsm logs

Added logs of Live storage migration failure

Comment 40 Kevin Alon Goldblatt 2015-02-24 14:58:07 UTC
Correction!
The Live storage migration failed on the PPC system

Comment 41 Adam Litke 2015-03-05 15:45:33 UTC
(In reply to Kevin Alon Goldblatt from comment #39)
> Created attachment 994737 [details]
> Engine and vdsm logs
> 
> Added logs of Live storage migration failure

The vdsm log shows no evidence of any Live Storage Migration related verbs being called.  Please upload logs that demonstrate the problem.  If the host running the VM was not SPM, please also upload the vdsm log for the SPM host.

Comment 42 Kevin Alon Goldblatt 2015-03-16 10:04:01 UTC
Adam,

1. There was only one host working at the time. The second host was in maintenance.
2.I noticed there is a 1 hour and 47 minutes difference between the host and the engine. 
3.I am waiting for the system to check again (its a time sharing system in use by someone else right now).

Comment 43 Kevin Alon Goldblatt 2015-03-18 15:37:40 UTC
Tested again with the same result on:
3.5.1 vt14


Outout from engine log:
-------------------------------------------

2015-03-18 14:44:58,026 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] Command VmReplicateDiskFinishVDSCommand(HostName = ibm-04, HostId = b90cf5e4-900d-4b19-bc58-176e0a57cdd3, vmId=37cf75ab-1a5a-4d98-bec7-23a28297e71a) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to VmReplicateDiskFinishVDS, error = Failed to change disk image
2015-03-18 14:44:58,026 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] FINISH, VmReplicateDiskFinishVDSCommand, log id: 45b0619d
2015-03-18 14:44:58,046 ERROR [org.ovirt.engine.core.bll.lsm.VmReplicateDiskFinishTaskHandler] (org.ovirt.thread.pool-7-thread-22) [684289f4] Failed VmReplicateDiskFinish (Disk 2ea5c096-370e-4d9e-afbc-d547d0faa0d7 , VM 37cf75ab-1a5a-4d98-bec7-23a28297e71a)
2015-03-18 14:44:58,047 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] Command org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to VmReplicateDiskFinishVDS, error = Failed to change disk image (Failed with error FAILED_CHANGE_CD_IS_MOUNTED and code 41)
2015-03-18 14:44:58,063 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] Reverting task unknown, handler: org.ovirt.engine.core.bll.lsm.VmReplicateDiskStartTaskHandler
2015-03-18 14:44:58,065 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] START, VmReplicateDiskFinishVDSCommand(HostName = ibm-04, HostId = b90cf5e4-900d-4b19-bc58-176e0a57cdd3, vmId=37cf75ab-1a5a-4d98-bec7-23a28297e71a), log id: 59692d93
2015-03-18 14:44:58,277 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] Failed in VmReplicateDiskFinishVDS method
2015-03-18 14:44:58,278 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] Command org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand return value 
 StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=55, mMessage=Drive replication error]]
2015-03-18 14:44:58,278 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] HostName = ibm-04
2015-03-18 14:44:58,278 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] Command VmReplicateDiskFinishVDSCommand(HostName = ibm-04, HostId = b90cf5e4-900d-4b19-bc58-176e0a57cdd3, vmId=37cf75ab-1a5a-4d98-bec7-23a28297e71a) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to VmReplicateDiskFinishVDS, error = Drive replication error, code = 55
2015-03-18 14:44:58,278 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (org.ovirt.thread.pool-7-thread-22) [684289f4] FINISH, VmReplicateDiskFinishVDSCommand, log id: 59692d93
2015-03-18 14:44:58,290 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-22) [684289f4] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk completed, handling the result.
2015-03-18 14:44:58,290 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-22) [684289f4] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type LiveMigrateDisk hasnt succeeded, not clearing tasks, will attempt again next polling.
2015-03-18 14:45:04,085 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-5) START, FullListVdsCommand(HostName = ibm-04, HostId = b90cf5e4-900d-4b19-bc58-176e0a57cdd3, vds=Host[ibm-04,b90cf5e4-900d-4b19-bc58-176e0a57cdd3], vmIds=[37cf75ab-1a5a-4d98-bec7-23a28297e71a]), log id: d819cb
2015-03-18 14:45:04,509 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-5) FINISH, FullListVdsCommand, return: [{displaySecurePort=-1, kvmEnable=true, nicModel=rtl8139,pv, keyboardLayout=en-us, displayIp=10.16.69.168, nice=0, displayNetwork=rhevm, timeOffset=0, transparentHugePages=true, vmId=37cf75ab-1a5a-4d98-bec7-23a28297e71a, acpiEnable=true, custom={}, spiceSslCipherSuite=DEFAULT, memSize=1024, displayPort=5900, smp=1, emulatedMachine=pseries, status=Up, vmType=kvm, memGuaranteedSize=1024, display=vnc, pid=31158, smartcardEnable=false, bootMenuEnable=false, tabletEnable=true, smpCoresPerSocket=1, spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, clientIp=, devices=[Ljava.lang.Object;@6b855edb, vmName=vm-test, cpuType=power8}], log id: d819cb
2015-03-18 14:45:04,512 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-5) Received a memballoon Device without an address when processing VM 37cf75ab-1a5a-4d98-bec7-23a28297e71a devices, skipping device: {alias=balloon0, specParams={model=none}, device=memballoon, type=balloon}
2015-03-18 14:45:07,713 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-69) BaseAsyncTask::onTaskEndSuccess: Task 7b14fe3e-a1de-404d-9b45-fbab18beff28 (Parent Command LiveMigrateDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2015-03-18 14:45:07,713 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-69) CommandAsyncTask::endActionIfNecessary: All tasks of command df8e2ef7-332e-4968-a8ca-e3660c7f0a8c has ended -> executing endAction
2015-03-18 14:45:07,713 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-69) CommandAsyncTask::endAction: Ending action for 1 tasks (command ID: df8e2ef7-332e-4968-a8ca-e3660c7f0a8c): calling endAction .
2015-03-18 14:45:07,713 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-29) CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction LiveMigrateDisk, executionIndex: 0
2015-03-18 14:45:07,762 ERROR [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-7-thread-29) [684289f4] Ending command with failure: org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand
2015-03-18 14:45:07,766 INFO  [org.ovirt.engine.core.bll.lsm.LiveMigrateDiskCommand] (org.ovirt.thread.pool-7-thread-29) [684289f4] Lock freed to object EngineLock [exclusiveLocks= , sharedLocks= key: 37cf75ab-1a5a-4d98-bec7-23a28297e71a value: VM
]
2015-03-18 14:45:07,804 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-29) [684289f4] Correlation ID: 684289f4, Job ID: 25a682f1-e7f1-4a37-bb48-40746bb40722, Call Stack: null, Custom Event ID: -1, Message: User admin@internal have failed to move disk vm-test_Disk1 to domain PPC-FC2.


FROM vdsm.log:
-------------------------

libvirtEventLoop::ERROR::2015-03-18 12:44:16,077::vm::4217::vm.Vm::(_onBlockJobEvent) vmId=`37cf75ab-1a5a-4d98-bec7-23a28297e71a`::Live merge completed for an unexpected path: /rhev/data-center/7a4cd49f-783d-48a4-a60d-36c0243aec14/cf0030d1-3a0d-4469-99db-ee58cb8684ec/images/873d732e-2627-4dbc-984f-54587ef75ed3/e65be5dd-84e3-41b0-8f67-ce702f5ebfce
libvirtEventLoop::ERROR::2015-03-18 12:44:16,170::vm::4217::vm.Vm::(_onBlockJobEvent) vmId=`37cf75ab-1a5a-4d98-bec7-23a28297e71a`::Live merge completed for an unexpected path: /rhev/data-center/7a4cd49f-783d-48a4-a60d-36c0243aec14/cf0030d1-3a0d-4469-99db-ee58cb8684ec/images/2ea5c096-370e-4d9e-afbc-d547d0faa0d7/dfc2eb51-2d4e-465a-8d76-a4bc28da920c
Thread-531::ERROR::2015-03-18 12:44:46,986::vm::4383::vm.Vm::(diskReplicateFinish) vmId=`37cf75ab-1a5a-4d98-bec7-23a28297e71a`::Unable to stop the replication for the drive: vda
Thread-531::ERROR::2015-03-18 12:46:39,308::vm::4383::vm.Vm::(diskReplicateFinish) vmId=`37cf75ab-1a5a-4d98-bec7-23a28297e71a`::Unable to stop the replication for the drive: vdb

Comment 44 Kevin Alon Goldblatt 2015-03-18 15:59:11 UTC
Created attachment 1003318 [details]
server, engine and vdsm logs

PLEASE NOTE!
There is a 2 hour time difference between the engine log and the vdsm log

Comment 45 Kevin Alon Goldblatt 2015-03-18 16:13:05 UTC
Created attachment 1003322 [details]
server, engine and vdsm logs

ADDED ADDITIONAL VDSM LOG

Comment 48 Allon Mureinik 2015-06-04 15:55:40 UTC
The needinfo has been there for too long.
Closing this bug as insufficiant_data. If you're able to reproduce, please provide the requested logs and reopen.

Comment 49 Elad 2015-11-30 09:04:49 UTC
Couldn't reproduce using latest ppc64le:

Red Hat Enterprise Linux Server release 7.2 (Maipo)
Linux ibm-p8-rhevm-03.rhts.eng.bos.redhat.com 3.10.0-327.2.1.el7.ppc64le #1 SMP Fri Nov 13 14:35:26 EST 2015 ppc64le ppc64le ppc64le GNU/Linux
vdsm-4.17.10.1-0.el7ev.noarch
libvirt-daemon-1.2.17-13.el7_2.2.ppc64le
qemu-img-rhev-2.3.0-31.el7_2.3.ppc64le


LSM succeeded over FC with different disks combination (thin/thin, thin/preacllocated, preacllocated/preacllocated).


Note You need to log in before you can comment on or make changes to this bug.