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.
Does this only reproduce on FC? Also, can you please attach libvirt logs? The failure seems to originate there.
Created attachment 962866 [details] New logs including libvirt from hosts 03 and 04
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).
I would also tried the workaround mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1102881#c34
(In reply to Michal Skrivanek from comment #4) I mean the behavior and error mentioned there...
(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?
(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.
Elad, Please try to check on your local setup with FC, we need to understand f it is related to PPC
(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.
Kevin/Elad, what selinux RPMs does the PPC env. have? Could you please run $ rpm -qa | grep selinux on both envs? Thanks!
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
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
result of testing in "permissive" mode as per comment #7?
(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:
Created attachment 969596 [details] Added new logs for need-info Added new logs for need-info
Daniel, please have a look
(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?
(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.
Created attachment 980578 [details] Added new logs for need-info
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?
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>
(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?
Yes, that seems like a good idea.
(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.
(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.
(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?
(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
3.4.5 build has shipped, no respins are planned. moving to 3.4.6 as candidate
I ran the same scenario as above with the fixes Adam provided. The Live Merge operation still fails.
(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?
Created attachment 994737 [details] Engine and vdsm logs Added logs of Live storage migration failure
Correction! The Live storage migration failed on the PPC system
(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.
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).
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
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
Created attachment 1003322 [details] server, engine and vdsm logs ADDED ADDITIONAL VDSM LOG
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.
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).