Bug 1520546 - LSM with continuous I/O to the VM failed and auto generated snapshot remains
Summary: LSM with continuous I/O to the VM failed and auto generated snapshot remains
Keywords:
Status: CLOSED DUPLICATE of bug 1312909
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: 4.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
high vote
Target Milestone: ovirt-4.3.4
: ---
Assignee: Benny Zlotnik
QA Contact: Elad
URL:
Whiteboard:
: 1679355 (view as bug list)
Depends On: 1312909
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-12-04 16:47 UTC by Raz Tamir
Modified: 2019-09-04 12:57 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-04-07 10:50:52 UTC
oVirt Team: Storage
rule-engine: ovirt-4.3+
aoconnor: blocker-


Attachments (Terms of Use)
engine and vdsm logs (1.15 MB, application/x-gzip)
2017-12-04 16:47 UTC, Raz Tamir
no flags Details

Description Raz Tamir 2017-12-04 16:47:33 UTC
Created attachment 1362764 [details]
engine and vdsm logs

Description of problem:
LSM with continuous I/O (dd) to the VM with 2 disks failed.
I executed dd if=/dev/vda of=/dev/sda bs=8MB and started LSM of the second disk without the OS.
/dev/vda is with OS.

From engine.log:

2017-12-04 18:37:48,841+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] START, VmReplicateDiskFinishVDSCommand(HostName = host_mixed_1, VmReplicateDiskParameters:{hostId='20a94a01-73e4-431f-a796-cb2238512967', vmId='2c9d5cc9-110f-40f4-88dc-348ed6b56889', storagePoolId='480d7e0f-4587-41d7-a045-a0fd8a41b6af', srcStorageDomainId='f48d3452-24f6-4701-aafe-be1faa4d4ca4', targetStorageDomainId='d2ae3fa6-8591-4845-b14e-ab1469ae9d32', imageGroupId='7de54695-ff9c-4aa2-986d-2acd5c3ae878', imageId='41bf5efd-0be5-4e24-8e18-f82a20fdae7c'}), log id: 6e85987c
2017-12-04 18:37:48,883+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] Failed in 'VmReplicateDiskFinishVDS' method
2017-12-04 18:37:48,892+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command VmReplicateDiskFinishVDS failed: Resource unavailable
2017-12-04 18:37:48,892+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand' return value 'StatusOnlyReturn [status=Status [code=40, message=Resource unavailable]]'
2017-12-04 18:37:48,892+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] HostName = host_mixed_1
2017-12-04 18:37:48,893+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] Command 'VmReplicateDiskFinishVDSCommand(HostName = host_mixed_1, VmReplicateDiskParameters:{hostId='20a94a01-73e4-431f-a796-cb2238512967', vmId='2c9d5cc9-110f-40f4-88dc-348ed6b56889', storagePoolId='480d7e0f-4587-41d7-a045-a0fd8a41b6af', srcStorageDomainId='f48d3452-24f6-4701-aafe-be1faa4d4ca4', targetStorageDomainId='d2ae3fa6-8591-4845-b14e-ab1469ae9d32', imageGroupId='7de54695-ff9c-4aa2-986d-2acd5c3ae878', imageId='41bf5efd-0be5-4e24-8e18-f82a20fdae7c'})' execution failed: VDSGenericException: VDSErrorException: Failed to VmReplicateDiskFinishVDS, error = Resource unavailable, code = 40
2017-12-04 18:37:48,893+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] FINISH, VmReplicateDiskFinishVDSCommand, log id: 6e85987c
2017-12-04 18:37:48,903+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] Failed VmReplicateDiskFinish (Disk '7de54695-ff9c-4aa2-986d-2acd5c3ae878', VM '2c9d5cc9-110f-40f4-88dc-348ed6b56889')
2017-12-04 18:37:48,904+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] Command 'LiveMigrateDisk' id: '5b8afa1e-e2a8-4be6-a097-300382a361f9' failed when attempting to perform the next operation, marking as FAILED '[de95db67-4d4f-466c-92d5-9f6575014fdf, a30d4c51-5853-4246-850d-3120306e49f8, ec2090a7-8ceb-478e-bb36-1ed97178e35a]'
2017-12-04 18:37:48,904+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [4c924332] Command 'LiveMigrateDisk' id: '5b8afa1e-e2a8-4be6-a097-300382a361f9' child commands '[de95db67-4d4f-466c-92d5-9f6575014fdf, a30d4c51-5853-4246-850d-3120306e49f8, ec2090a7-8ceb-478e-bb36-1ed97178e35a]' executions were completed, status 'FAILED'
2017-12-04 18:37:49,960+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Ending command 'org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand' with failure.
2017-12-04 18:37:49,960+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Failed during live storage migration of disk '7de54695-ff9c-4aa2-986d-2acd5c3ae878' of vm '2c9d5cc9-110f-40f4-88dc-348ed6b56889', attempting to end replication before deleting the target disk
2017-12-04 18:37:49,964+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] START, VmReplicateDiskFinishVDSCommand(HostName = host_mixed_1, VmReplicateDiskParameters:{hostId='20a94a01-73e4-431f-a796-cb2238512967', vmId='2c9d5cc9-110f-40f4-88dc-348ed6b56889', storagePoolId='480d7e0f-4587-41d7-a045-a0fd8a41b6af', srcStorageDomainId='f48d3452-24f6-4701-aafe-be1faa4d4ca4', targetStorageDomainId='f48d3452-24f6-4701-aafe-be1faa4d4ca4', imageGroupId='7de54695-ff9c-4aa2-986d-2acd5c3ae878', imageId='41bf5efd-0be5-4e24-8e18-f82a20fdae7c'}), log id: 2d30d3a6
2017-12-04 18:37:50,055+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Failed in 'VmReplicateDiskFinishVDS' method
2017-12-04 18:37:50,064+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command VmReplicateDiskFinishVDS failed: Resource unavailable
2017-12-04 18:37:50,065+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand' return value 'StatusOnlyReturn [status=Status [code=40, message=Resource unavailable]]'
2017-12-04 18:37:50,065+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] HostName = host_mixed_1
2017-12-04 18:37:50,065+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Command 'VmReplicateDiskFinishVDSCommand(HostName = host_mixed_1, VmReplicateDiskParameters:{hostId='20a94a01-73e4-431f-a796-cb2238512967', vmId='2c9d5cc9-110f-40f4-88dc-348ed6b56889', storagePoolId='480d7e0f-4587-41d7-a045-a0fd8a41b6af', srcStorageDomainId='f48d3452-24f6-4701-aafe-be1faa4d4ca4', targetStorageDomainId='f48d3452-24f6-4701-aafe-be1faa4d4ca4', imageGroupId='7de54695-ff9c-4aa2-986d-2acd5c3ae878', imageId='41bf5efd-0be5-4e24-8e18-f82a20fdae7c'})' execution failed: VDSGenericException: VDSErrorException: Failed to VmReplicateDiskFinishVDS, error = Resource unavailable, code = 40
2017-12-04 18:37:50,065+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] FINISH, VmReplicateDiskFinishVDSCommand, log id: 2d30d3a6
2017-12-04 18:37:50,065+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Replication end of disk '7de54695-ff9c-4aa2-986d-2acd5c3ae878' in vm '2c9d5cc9-110f-40f4-88dc-348ed6b56889' back to the source failed, skipping deletion of the target disk
2017-12-04 18:37:50,075+02 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Trying to release exclusive lock which does not exist, lock key: '2c9d5cc9-110f-40f4-88dc-348ed6b56889LIVE_STORAGE_MIGRATION'
2017-12-04 18:37:50,075+02 INFO  [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] Lock freed to object 'EngineLock:{exclusiveLocks='[2c9d5cc9-110f-40f4-88dc-348ed6b56889=LIVE_STORAGE_MIGRATION]', sharedLocks=''}'
2017-12-04 18:37:50,150+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-36) [4c924332] EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), User admin@internal-authz have failed to move disk test_Disk1 to domain iscsi_1.


vdsm.log:

2017-12-04 18:37:48,848+0200 INFO  (jsonrpc/1) [api.virt] START diskReplicateFinish(srcDisk={'device': 'disk', 'poolID': '480d7e0f-4587-41d7-a045-a0fd8a41b6af', 'volumeID': '41bf5efd-0be5-4e24-8e18-f82a20fdae7c', 'domainID': 'f48d3452-24f
6-4701-aafe-be1faa4d4ca4', 'imageID': '7de54695-ff9c-4aa2-986d-2acd5c3ae878'}, dstDisk={'device': 'disk', 'poolID': '480d7e0f-4587-41d7-a045-a0fd8a41b6af', 'volumeID': '41bf5efd-0be5-4e24-8e18-f82a20fdae7c', 'domainID': 'd2ae3fa6-8591-484
5-b14e-ab1469ae9d32', 'imageID': '7de54695-ff9c-4aa2-986d-2acd5c3ae878'}) from=::ffff:10.35.161.127,59390, flow_id=4c924332 (api:46)
2017-12-04 18:37:48,869+0200 ERROR (jsonrpc/1) [virt.vm] (vmId='2c9d5cc9-110f-40f4-88dc-348ed6b56889') Replication job unfinished (drive: 'sda', srcDisk: {'device': 'disk', 'poolID': '480d7e0f-4587-41d7-a045-a0fd8a41b6af', 'volumeID': '41
bf5efd-0be5-4e24-8e18-f82a20fdae7c', 'domainID': 'f48d3452-24f6-4701-aafe-be1faa4d4ca4', 'imageID': '7de54695-ff9c-4aa2-986d-2acd5c3ae878'}, job: {'end': 2438529024L, 'bandwidth': 0L, 'type': 2, 'cur': 620560384L}) (vm:4421)
2017-12-04 18:37:48,878+0200 INFO  (jsonrpc/1) [api.virt] FINISH diskReplicateFinish return={'status': {'message': 'Resource unavailable', 'code': 40}} from=::ffff:10.35.161.127,59390, flow_id=4c924332 (api:52)
2017-12-04 18:37:48,879+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish failed (error 40) in 0.03 seconds (__init__:573)
2017-12-04 18:37:50,027+0200 INFO  (jsonrpc/6) [api.virt] START diskReplicateFinish(srcDisk={'device': 'disk', 'poolID': '480d7e0f-4587-41d7-a045-a0fd8a41b6af', 'volumeID': '41bf5efd-0be5-4e24-8e18-f82a20fdae7c', 'domainID': 'f48d3452-24f
6-4701-aafe-be1faa4d4ca4', 'imageID': '7de54695-ff9c-4aa2-986d-2acd5c3ae878'}, dstDisk={'device': 'disk', 'poolID': '480d7e0f-4587-41d7-a045-a0fd8a41b6af', 'volumeID': '41bf5efd-0be5-4e24-8e18-f82a20fdae7c', 'domainID': 'f48d3452-24f6-470
1-aafe-be1faa4d4ca4', 'imageID': '7de54695-ff9c-4aa2-986d-2acd5c3ae878'}) from=::ffff:10.35.161.127,59390, flow_id=4c924332 (api:46)
2017-12-04 18:37:50,050+0200 ERROR (jsonrpc/6) [virt.vm] (vmId='2c9d5cc9-110f-40f4-88dc-348ed6b56889') Replication job unfinished (drive: 'sda', srcDisk: {'device': 'disk', 'poolID': '480d7e0f-4587-41d7-a045-a0fd8a41b6af', 'volumeID': '41
bf5efd-0be5-4e24-8e18-f82a20fdae7c', 'domainID': 'f48d3452-24f6-4701-aafe-be1faa4d4ca4', 'imageID': '7de54695-ff9c-4aa2-986d-2acd5c3ae878'}, job: {'end': 2474835968L, 'bandwidth': 0L, 'type': 2, 'cur': 648216576L}) (vm:4421)



Version-Release number of selected component (if applicable):
rhv-4.2.0-0.5.master.el7
vdsm-api-4.20.8-1.el7ev.noarch

How reproducible:
100%

Steps to Reproduce:
1. Create VM with OS disk + 1 more thin provision disk
2. Start the VM and execute #dd if=/dev/vda of=/dev/sda
  2.1 /dev/vda disk with OS, /dev/sda 2nd thin disk
3. LSM the 2nd disk to different storage domain (I tested same type - iscsi)

Actual results:
LSM fails and the auto-generated snapshot remains

Expected results:


Additional info:

Comment 1 Allon Mureinik 2017-12-05 11:44:07 UTC
I sincerely doubt this is a regression. Raz, can you execute the same plan on an older build/version and attach logs from a successful run?

Comment 2 Allon Mureinik 2017-12-05 11:45:25 UTC
Benny, other than (finally) implementing bug 1312909, is there anything we can do here?

Comment 3 Raz Tamir 2017-12-05 16:11:01 UTC
(In reply to Allon Mureinik from comment #1)
> I sincerely doubt this is a regression. Raz, can you execute the same plan
> on an older build/version and attach logs from a successful run?

You are right Allon,

It didn't pass on 4.1 too:

engine.log:

2017-12-05 18:00:19,115+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] START, VmReplicateDiskFinishVDSCommand(HostName = host_mixed_3, 
VmReplicateDiskParameters:{runAsync='true', hostId='aed9971c-963e-4fd7-a652-a7839563d538', vmId='f724cc17-93ea-423c-86c6-5732253c25b4', storagePoolId='0ef229cd-a746-4a25-be21-39ffb68e1c5e', srcStorageDomainId='7d12be36-3538-4e59-94da-a1a6
edef01fb', targetStorageDomainId='13ecab19-539f-444b-a7a4-cd9b149791cb', imageGroupId='d7fb672f-0729-4d5c-b343-02c6417644d5', imageId='f645fb3b-f200-408f-922d-a18408f37cff'}), log id: 15a5685d
2017-12-05 18:00:19,314+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] Failed in 'VmReplicateDiskFinishVDS' method
2017-12-05 18:00:19,327+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, C
all Stack: null, Custom ID: null, Custom Event ID: -1, Message: VDSM host_mixed_3 command VmReplicateDiskFinishVDS failed: Resource unavailable
2017-12-05 18:00:19,327+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDi
skFinishVDSCommand' return value 'StatusOnlyReturn [status=Status [code=40, message=Resource unavailable]]'
2017-12-05 18:00:19,327+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] HostName = host_mixed_3
2017-12-05 18:00:19,328+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'VmReplicateDiskFinishVDSCommand(HostName = host_mixed_3
, VmReplicateDiskParameters:{runAsync='true', hostId='aed9971c-963e-4fd7-a652-a7839563d538', vmId='f724cc17-93ea-423c-86c6-5732253c25b4', storagePoolId='0ef229cd-a746-4a25-be21-39ffb68e1c5e', srcStorageDomainId='7d12be36-3538-4e59-94da-a1
a6edef01fb', targetStorageDomainId='13ecab19-539f-444b-a7a4-cd9b149791cb', imageGroupId='d7fb672f-0729-4d5c-b343-02c6417644d5', imageId='f645fb3b-f200-408f-922d-a18408f37cff'})' execution failed: VDSGenericException: VDSErrorException: Fa
iled to VmReplicateDiskFinishVDS, error = Resource unavailable, code = 40
2017-12-05 18:00:19,328+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] FINISH, VmReplicateDiskFinishVDSCommand, log id: 15a5685d
2017-12-05 18:00:19,347+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] Failed VmReplicateDiskFinish (Disk 'd7fb672f-0729-4d5c-b343-02c6417644d5', VM
 'f724cc17-93ea-423c-86c6-5732253c25b4')
2017-12-05 18:00:19,347+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'LiveMigrateDisk' id: '31e43ac6-a78a-4aee-81b5-3e483f2f506a' failed
 when attempting to perform the next operation, marking as FAILED '[fe6b9765-d444-4a7f-9480-7f14af5055ce, b2ee940d-032b-408f-a074-965db38a5f82]'
2017-12-05 18:00:19,347+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler4) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'LiveMigrateDisk' id: '31e43ac6-a78a-4aee-81b5-3e483f2f506a' child 
commands '[fe6b9765-d444-4a7f-9480-7f14af5055ce, b2ee940d-032b-408f-a074-965db38a5f82]' executions were completed, status 'FAILED'
2017-12-05 18:00:20,405+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Ending command 'org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand'
 with failure.
2017-12-05 18:00:20,406+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Failed during live storage migration of disk 'd7fb672f-0729-4d5c-b343-02c6417
644d5' of vm 'f724cc17-93ea-423c-86c6-5732253c25b4', attempting to end replication before deleting the target disk
2017-12-05 18:00:20,406+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] START, VmReplicateDiskFinishVDSCommand(HostName = host_mixed_3, 
VmReplicateDiskParameters:{runAsync='true', hostId='aed9971c-963e-4fd7-a652-a7839563d538', vmId='f724cc17-93ea-423c-86c6-5732253c25b4', storagePoolId='0ef229cd-a746-4a25-be21-39ffb68e1c5e', srcStorageDomainId='7d12be36-3538-4e59-94da-a1a6
edef01fb', targetStorageDomainId='7d12be36-3538-4e59-94da-a1a6edef01fb', imageGroupId='d7fb672f-0729-4d5c-b343-02c6417644d5', imageId='f645fb3b-f200-408f-922d-a18408f37cff'}), log id: 4accae0f
2017-12-05 18:00:20,441+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Failed in 'VmReplicateDiskFinishVDS' method
2017-12-05 18:00:20,451+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, C
all Stack: null, Custom ID: null, Custom Event ID: -1, Message: VDSM host_mixed_3 command VmReplicateDiskFinishVDS failed: Resource unavailable
2017-12-05 18:00:20,451+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDi
skFinishVDSCommand' return value 'StatusOnlyReturn [status=Status [code=40, message=Resource unavailable]]'
2017-12-05 18:00:20,451+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] HostName = host_mixed_3
2017-12-05 18:00:20,451+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'VmReplicateDiskFinishVDSCommand(HostName = host_mixed_3
, VmReplicateDiskParameters:{runAsync='true', hostId='aed9971c-963e-4fd7-a652-a7839563d538', vmId='f724cc17-93ea-423c-86c6-5732253c25b4', storagePoolId='0ef229cd-a746-4a25-be21-39ffb68e1c5e', srcStorageDomainId='7d12be36-3538-4e59-94da-a1
a6edef01fb', targetStorageDomainId='7d12be36-3538-4e59-94da-a1a6edef01fb', imageGroupId='d7fb672f-0729-4d5c-b343-02c6417644d5', imageId='f645fb3b-f200-408f-922d-a18408f37cff'})' execution failed: VDSGenericException: VDSErrorException: Fa
iled to VmReplicateDiskFinishVDS, error = Resource unavailable, code = 40
2017-12-05 18:00:20,451+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] FINISH, VmReplicateDiskFinishVDSCommand, log id: 4accae0f
2017-12-05 18:00:20,451+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Replication end of disk 'd7fb672f-0729-4d5c-b343-02c6417644d5' in vm 'f724cc1
7-93ea-423c-86c6-5732253c25b4' back to the source failed, skipping deletion of the target disk
2017-12-05 18:00:20,486+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [8fc83505-f42b-45d5-bc55-c09f8284c787] EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), Correlation ID: 8f
c83505-f42b-45d5-bc55-c09f8284c787, Job ID: 961cddac-8338-4b67-89de-76759f732f85, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: User admin@internal-authz have failed to move disk test_Disk1 to domain iscsi_1.

....

*** Remove snapshot starts ***

2017-12-05 18:00:27,272+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Failed in 'MergeVDS' method
2017-12-05 18:00:27,286+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-1) [8fc83505-f42b-45d5-bc55-c09f8284c787] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: VDSM host_mixed_3 command MergeVDS failed: Merge failed
2017-12-05 18:00:27,287+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand' return value 'StatusOnlyReturn [status=Status [code=52, message=Merge failed]]'
2017-12-05 18:00:27,287+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-1) [8fc83505-f42b-45d5-bc55-c09f8284c787] HostName = host_mixed_3
2017-12-05 18:00:27,287+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'MergeVDSCommand(HostName = host_mixed_3, MergeVDSCommandParameters:{runAsync='true', hostId='aed9971c-963e-4fd7-a652-a7839563d538', vmId='f724cc17-93ea-423c-86c6-5732253c25b4', storagePoolId='0ef229cd-a746-4a25-be21-39ffb68e1c5e', storageDomainId='7d12be36-3538-4e59-94da-a1a6edef01fb', imageGroupId='d7fb672f-0729-4d5c-b343-02c6417644d5', imageId='f645fb3b-f200-408f-922d-a18408f37cff', baseImageId='ad0ce530-8947-4ed8-8e58-ea9c6867784c', topImageId='f645fb3b-f200-408f-922d-a18408f37cff', bandwidth='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52
2017-12-05 18:00:27,287+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-1) [8fc83505-f42b-45d5-bc55-c09f8284c787] FINISH, MergeVDSCommand, log id: 50efb8be
2017-12-05 18:00:27,287+02 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-5-thread-1) [8fc83505-f42b-45d5-bc55-c09f8284c787] Engine exception thrown while sending merge command: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 (Failed with error mergeErr and code 52)
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2166) [bll.jar:]
        at org.ovirt.engine.core.bll.MergeCommand.executeCommand(MergeCommand.java:45) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1251) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1391) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2055) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137) [utils.jar:]

....

2017-12-05 18:00:31,140+02 ERROR [org.ovirt.engine.core.bll.MergeStatusCommand] (pool-5-thread-2) [8fc83505-f42b-45d5-bc55-c09f8284c787] Failed to live merge, still in volume chain: [f645fb3b-f200-408f-922d-a18408f37cff, ad0ce530-8947-4ed8-8e58-ea9c6867784c]
2017-12-05 18:00:32,116+02 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler6) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command id: '9f2ccf33-ee4e-41fb-a798-9bd05fd2a046 failed child command status for step 'MERGE_STATUS'
2017-12-05 18:00:32,116+02 INFO  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommandCallback] (DefaultQuartzScheduler6) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'RemoveSnapshotSingleDiskLive' id: '9f2ccf33-ee4e-41fb-a798-9bd05fd2a046' child commands '[aa4e1a2d-6192-47f5-95f5-3f9fa2dfa0ce, 7f7404c2-5a46-4786-9e3c-950b5eef9761, c5aff60f-a542-4f39-a291-4e15fe76cb7e]' executions were completed, status 'FAILED'
2017-12-05 18:00:33,145+02 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler10) [8fc83505-f42b-45d5-bc55-c09f8284c787] Merging of snapshot '55adcd23-acc3-4894-988b-874276e6ffc4' images 'ad0ce530-8947-4ed8-8e58-ea9c6867784c'..'f645fb3b-f200-408f-922d-a18408f37cff' failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation.
2017-12-05 18:00:33,164+02 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler10) [8fc83505-f42b-45d5-bc55-c09f8284c787] Ending command 'org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand' with failure.
2017-12-05 18:00:34,183+02 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler8) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'RemoveSnapshot' id: '7a16dd33-1012-42b8-abc2-d75f1d6e27d6' child commands '[9f2ccf33-ee4e-41fb-a798-9bd05fd2a046]' executions were completed, status 'FAILED'
2017-12-05 18:00:35,390+02 ERROR [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (DefaultQuartzScheduler10) [8fc83505-f42b-45d5-bc55-c09f8284c787] Ending command 'org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand' with failure.
2017-12-05 18:00:35,521+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler10) [8fc83505-f42b-45d5-bc55-c09f8284c787] EVENT_ID: USER_REMOVE_SNAPSHOT_FINISHED_FAILURE(357), Correlation ID: 8fc83505-f42b-45d5-bc55-c09f8284c787, Job ID: 993bf6f0-5482-4c7b-8932-e8cfa977c338, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Failed to delete snapshot 'Auto-generated for Live Storage Migration' for VM 'test'.
2017-12-05 18:00:35,695+02 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler4) [50016382] Setting new tasks map. The map contains now 2 tasks
2017-12-05 18:00:35,791+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler10) [8fc83505-f42b-45d5-bc55-c09f8284c787] Command 'LiveMigrateVmDisks' id: 'a7a24454-675c-4cdb-8d77-d9a056c565fc' child commands '[88da3d27-fed3-4348-bd7f-97fb4e0a1bd0, 31e43ac6-a78a-4aee-81b5-3e483f2f506a, 7a16dd33-1012-42b8-abc2-d75f1d6e27d6]' executions were completed, status 'FAILED'
2017-12-05 18:00:37,217+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateVmDisksCommand] (DefaultQuartzScheduler9) [8fc83505-f42b-45d5-bc55-c09f8284c787] Ending command 'org.ovirt.engine.core.bll.storage.lsm.LiveMigrateVmDisksCommand' with failure.


vdsm.log (Remove Auto-generated snapshot fails):

2017-12-05 18:00:27,044+0200 INFO  (jsonrpc/6) [virt.vm] (vmId='f724cc17-93ea-423c-86c6-5732253c25b4') Starting merge with jobUUID='90e3302f-59ab-4303-928f-05e7ebbb8e7d', original chain=ad0ce530-8947-4ed8-8e58-ea9c6867784c < f645fb3b-f200-408f-922d-a18408f37cff (top), disk='sda', base='sda[1]', top=None, bandwidth=0, flags=12 (vm:4943)
2017-12-05 18:00:27,145+0200 ERROR (jsonrpc/6) [virt.vm] (vmId='f724cc17-93ea-423c-86c6-5732253c25b4') Live merge failed (job: 90e3302f-59ab-4303-928f-05e7ebbb8e7d) (vm:4949)
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/vm.py", line 4947, in merge
    bandwidth, flags)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 69, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 123, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 1006, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 678, in blockCommit
    if ret == -1: raise libvirtError ('virDomainBlockCommit() failed', dom=self)
libvirtError: block copy still active: disk 'sda' already in active block job


So this is not a regression - should I open a bug for 4.1 too?

Comment 4 Allon Mureinik 2017-12-06 17:06:42 UTC
(In reply to Raz Tamir from comment #3)
> So this is not a regression - should I open a bug for 4.1 too?
I don't think we need to of them - there definitely is a bug, and it definitely needs to be fixed.
Once we have a fix, we can assess whether it's feasible/worth the effort of fixing in 4.1 too.

Comment 5 Raz Tamir 2018-08-22 14:30:45 UTC
Do we have plans to fix it in 4.2.z?
In case not, please remove the blocker+ flag

Comment 7 Benny Zlotnik 2019-04-07 10:50:52 UTC

*** This bug has been marked as a duplicate of bug 1312909 ***

Comment 8 Sahina Bose 2019-09-04 12:57:46 UTC
*** Bug 1679355 has been marked as a duplicate of this bug. ***


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