Bug 1776003

Created attachment 1639218 [details]
logs

Description of problem:
VM became unresponsive after VmReplicateDiskFinishVDSCommand and caused LSM failure and VM destroy error.


Engine log:
2019-11-20 08:20:19,230+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] START, VmReplicateDiskFinishVDSCommand(HostName = host_mixed_2, VmReplicateDiskParameters:{hostId='666bdfa6-a483-431e-891a-1e9eb2197278', vmId='cfda2240-2db8-430b-9a09-2d37b97e33d6', storagePoolId='1b798999-f94b-46f3-850a-b002ab228fd6', srcStorageDomainId='288b173a-cb9e-444d-be42-43ec6aa73d5f', targetStorageDomainId='56c56243-35c2-4027-b095-0d013c12e1dd', imageGroupId='dd1b4ba9-3a01-4eba-b8bb-aeec6f1e048a', imageId='ba60a7f5-9893-474c-b7a4-ce67088a82de'}), log id: 27ed9a7a
2019-11-20 08:20:47,343+02 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-80) [] Setting new tasks map. The map contains now 2 tasks
2019-11-20 08:21:11,485+02 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] VM 'cfda2240-2db8-430b-9a09-2d37b97e33d6'(vm_TestCase4925_2008172480) moved from 'Up' --> 'NotResponding'
2019-11-20 08:21:11,566+02 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] EVENT_ID: VM_NOT_RESPONDING(126), VM vm_TestCase4925_2008172480 is not responding.
2019-11-20 08:21:17,344+02 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [] Setting new tasks map. The map contains now 0 tasks
2019-11-20 08:21:17,344+02 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [] Cleared all tasks of pool '1b798999-f94b-46f3-850a-b002ab228fd6'.
2019-11-20 08:23:19,442+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_2 command VmReplicateDiskFinishVDS failed: Message timeout which can be caused by communication issues
2019-11-20 08:23:19,443+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand' return value 'StatusOnlyReturn [status=Status [code=5022, message=Message timeout which can be caused by communication issues]]'
2019-11-20 08:23:19,443+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] HostName = host_mixed_2
2019-11-20 08:23:19,443+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] Command 'VmReplicateDiskFinishVDSCommand(HostName = host_mixed_2, VmReplicateDiskParameters:{hostId='666bdfa6-a483-431e-891a-1e9eb2197278', vmId='cfda2240-2db8-430b-9a09-2d37b97e33d6', storagePoolId='1b798999-f94b-46f3-850a-b002ab228fd6', srcStorageDomainId='288b173a-cb9e-444d-be42-43ec6aa73d5f', targetStorageDomainId='56c56243-35c2-4027-b095-0d013c12e1dd', imageGroupId='dd1b4ba9-3a01-4eba-b8bb-aeec6f1e048a', imageId='ba60a7f5-9893-474c-b7a4-ce67088a82de'})' execution failed: VDSGenericException: VDSNetworkException: Message timeout which can be caused by communication issues
2019-11-20 08:23:19,443+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] FINISH, VmReplicateDiskFinishVDSCommand, return: , log id: 27ed9a7a
2019-11-20 08:23:19,443+02 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (EE-ManagedThreadFactory-engine-Thread-27924) [disks_syncAction_202f4230-8e2e-4b9b] Clearing domains data for host host_mixed_2
2019-11-20 08:23:19,443+02 WARN  [org.ovirt.engine.core.vdsbroker.VdsManager] (EE-ManagedThreadFactory-engine-Thread-27924) [disks_syncAction_202f4230-8e2e-4b9b] Host 'host_mixed_2' is not responding.
2019-11-20 08:23:19,449+02 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-27924) [disks_syncAction_202f4230-8e2e-4b9b] EVENT_ID: VDS_HOST_NOT_RESPONDING(9,027), Host host_mixed_2 is not responding. Host cannot be fenced automatically because power management for the host is disabled.
2019-11-20 08:23:19,464+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] Failed VmReplicateDiskFinish (Disk 'dd1b4ba9-3a01-4eba-b8bb-aeec6f1e048a', VM 'cfda2240-2db8-430b-9a09-2d37b97e33d6')
2019-11-20 08:23:19,464+02 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] Command 'LiveMigrateDisk' id: 'cfb39447-69cb-489a-b1d1-10c634e76f3a' with children [8a6ee64e-1f55-4d05-9742-f1a8a6510603, da329ab8-6758-4e69-a24a-00e36500fc06, 88a452ba-e71a-4d18-bac1-6e0680d80c15] failed when attempting to perform the next operation, marking as 'ACTIVE'
2019-11-20 08:23:19,464+02 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] EngineException: Message timeout which can be caused by communication issues (Failed with error VDS_NETWORK_ERROR and code 5022): org.ovirt.engine.core.common.errors.EngineException: EngineException: Message timeout which can be caused by communication issues (Failed with error VDS_NETWORK_ERROR and code 5022)
	at org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.replicateDiskFinish(LiveMigrateDiskCommand.java:429) [bll.jar:]
	at org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.completeLiveMigration(LiveMigrateDiskCommand.java:393) [bll.jar:]
	at org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.performNextOperation(LiveMigrateDiskCommand.java:246) [bll.jar:]
	at org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback.childCommandsExecutionEnded(SerialChildCommandsExecutionCallback.java:32) [bll.jar:]
	at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java:77) [bll.jar:]
	at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:175) [bll.jar:]
	at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109) [bll.jar:]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_232]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [rt.jar:1.8.0_232]
	at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
	at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_232]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_232]
	at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_232]
	at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]

2019-11-20 08:23:19,465+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-12) [disks_syncAction_202f4230-8e2e-4b9b] Command 'LiveMigrateDisk' id: 'cfb39447-69cb-489a-b1d1-10c634e76f3a' child commands '[8a6ee64e-1f55-4d05-9742-f1a8a6510603, da329ab8-6758-4e69-a24a-00e36500fc06, 88a452ba-e71a-4d18-bac1-6e0680d80c15]' executions were completed, status 'FAILED'
2019-11-20 08:23:20,661+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-44) [disks_syncAction_202f4230-8e2e-4b9b] Ending command 'org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand' with failure.
2019-11-20 08:23:20,662+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-44) [disks_syncAction_202f4230-8e2e-4b9b] Failed during live storage migration of disk 'dd1b4ba9-3a01-4eba-b8bb-aeec6f1e048a' of vm 'cfda2240-2db8-430b-9a09-2d37b97e33d6', attempting to end replication before deleting the target disk
2019-11-20 08:23:50,670+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-44) [disks_syncAction_202f4230-8e2e-4b9b] Failed in 'VmReplicateDiskFinishVDS' method
2019-11-20 08:23:50,681+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-44) [disks_syncAction_202f4230-8e2e-4b9b] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_2 command VmReplicateDiskFinishVDS failed: General Exception: ('Timed out during operation: cannot acquire state change lock (held by monitor=remoteDispatchDomainBlockJobAbort)',)
2019-11-20 08:23:50,682+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-44) [disks_syncAction_202f4230-8e2e-4b9b] Command 'VmReplicateDiskFinishVDSCommand(HostName = host_mixed_2, VmReplicateDiskParameters:{hostId='666bdfa6-a483-431e-891a-1e9eb2197278', vmId='cfda2240-2db8-430b-9a09-2d37b97e33d6', storagePoolId='1b798999-f94b-46f3-850a-b002ab228fd6', srcStorageDomainId='288b173a-cb9e-444d-be42-43ec6aa73d5f', targetStorageDomainId='288b173a-cb9e-444d-be42-43ec6aa73d5f', imageGroupId='dd1b4ba9-3a01-4eba-b8bb-aeec6f1e048a', imageId='ba60a7f5-9893-474c-b7a4-ce67088a82de'})' execution failed: VDSGenericException: VDSErrorException: Failed to VmReplicateDiskFinishVDS, error = General Exception: ('Timed out during operation: cannot acquire state change lock (held by monitor=remoteDispatchDomainBlockJobAbort)',), code = 100
2019-11-20 08:23:50,682+02 ERROR [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-44) [disks_syncAction_202f4230-8e2e-4b9b] Replication end of disk 'dd1b4ba9-3a01-4eba-b8bb-aeec6f1e048a' in vm 'cfda2240-2db8-430b-9a09-2d37b97e33d6' back to the source failed, skipping deletion of the target disk
2019-11-20 08:23:50,798+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-44) [disks_syncAction_202f4230-8e2e-4b9b] EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), User admin@internal-authz have failed to move disk disk_virtio_scsicow_2008174840 to domain iscsi_1.
2019-11-20 08:23:53,762+02 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-86) [] Operation Failed: [Cannot move Virtual Disk. The Virtual Machine should be either in Up or Paused status.]
2019-11-20 08:23:56,669+02 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-71) [] VM 'cfda2240-2db8-430b-9a09-2d37b97e33d6'(vm_TestCase4925_2008172480) moved from 'NotResponding' --> 'PoweringDown'
2019-11-20 08:24:24,349+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] Failed in 'DestroyVDS' method
2019-11-20 08:24:24,355+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_2 command DestroyVDS failed: Virtual machine destroy error
2019-11-20 08:24:24,356+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] Command 'DestroyVDSCommand(HostName = host_mixed_2, DestroyVmVDSCommandParameters:{hostId='666bdfa6-a483-431e-891a-1e9eb2197278', vmId='cfda2240-2db8-430b-9a09-2d37b97e33d6', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='false'})' execution failed: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Virtual machine destroy error, code = 42
2019-11-20 08:24:24,356+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] FINISH, DestroyVDSCommand, return: , log id: 25d9bfc5
2019-11-20 08:24:24,356+02 ERROR [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] Failed to destroy VM 'cfda2240-2db8-430b-9a09-2d37b97e33d6' in VDS = '666bdfa6-a483-431e-891a-1e9eb2197278' , error = 'org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Virtual machine destroy error, code = 42'
2019-11-20 08:24:24,356+02 INFO  [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] FINISH, DestroyVmVDSCommand, return: , log id: 2ca3017f
2019-11-20 08:24:24,356+02 ERROR [org.ovirt.engine.core.bll.StopVmCommand] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] Command 'org.ovirt.engine.core.bll.StopVmCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Virtual machine destroy error, code = 42 (Failed with error destroyErr and code 42)
2019-11-20 08:24:24,367+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-86) [vms_syncAction_158dc9fe-bc60-4869] EVENT_ID: USER_FAILED_STOP_VM(56), Failed to power off VM vm_TestCase4925_2008172480 (Host: host_mixed_2, User: admin@internal-authz).
2019-11-20 08:24:24,371+02 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-86) [] Operation Failed: [Virtual machine destroy error]


VDSM:
2019-11-20 08:23:50,668+0200 ERROR (jsonrpc/7) [api] FINISH diskReplicateFinish error=Timed out during operation: cannot acquire state change lock (held by monitor=remoteDispatchDomainBlockJobAbort) (api:134)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 124, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 580, in diskReplicateFinish
    return self.vm.diskReplicateFinish(srcDisk, dstDisk)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4650, in diskReplicateFinish
    blkJobInfo = self._dom.blockJobInfo(drive.name, 0)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 108, in f
    raise toe
TimeoutError: Timed out during operation: cannot acquire state change lock (held by monitor=remoteDispatchDomainBlockJobAbort)

Version-Release number of selected component (if applicable):
vdsm-4.30.38-1.el7ev.x86_64
ovirt-engine-4.3.7.2-0.1.el7.noarch

How reproducible:
Once (automation TC)

Steps to Reproduce:
1. create VM with os
2. Attach read-only disks to the VM (all possible permutation)
3. Activate the disks
4. try to move them (LSM) to the another storage domain

Actual results:
Operation should succeed

Expected results:
Operation failed.

Additional info:
Relevant logs are attached