Bug 1514901 - Avoid preparing and tearing down images during create snapshot while the VM isn't down
Summary: Avoid preparing and tearing down images during create snapshot while the VM i...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: 4.1.7.6
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ovirt-4.1.8
: ---
Assignee: Ala Hino
QA Contact: Raz Tamir
URL:
Whiteboard:
: 1532464 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-11-19 11:01 UTC by Raz Tamir
Modified: 2021-03-11 18:16 UTC (History)
4 users (show)

Fixed In Version: ovirt-engine-4.1.8.1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-12-11 16:30:45 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-4.1+


Attachments (Terms of Use)
engine and vdsm logs (447.14 KB, application/x-gzip)
2017-11-19 11:01 UTC, Raz Tamir
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 3314421 0 None None None 2018-01-09 15:55:48 UTC
oVirt gerrit 84350 0 ovirt-engine-4.1 MERGED core: Avoid prepare or teardown image during live create snapshot 2017-11-20 08:57:06 UTC

Description Raz Tamir 2017-11-19 11:01:46 UTC
Created attachment 1355083 [details]
engine and vdsm logs

If the VM is paused during creating a snapshot, there is an attempt to tear down the image. Although the exception is ignored, and the operation isn't failed, we shouldn't attempt to tear down images if the VM isn't down.

How reproducible:
Occasionally if the VM is paused during a create snapshot operation

Steps to Reproduce:
1. Create a snapshot while the VM is up

Actual results:
The snapshot is successfully created; however, the volume is torn down. Following exception can be seen in the logs:

Engine:
2017-11-18 12:52:06,369+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] 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_2 command TeardownImageVDS failed: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  L
ogical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical
 volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',)
2017-11-18 12:52:06,369+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] Command 'TeardownImageVDSCommand(HostName = host_mixed_2, ImageActionsVDSCommandParameters:{runAsync='true', hostId='5ae36066-4b80-4f31-a8c0-bb67ed2004da'})' execution failed: VDSGenericException: VDSErrorException: Failed in vdscommand to TeardownImageVDS, error = Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',)
2017-11-18 12:52:06,369+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] FINISH, TeardownImageVDSCommand, log id: 743649a1
2017-11-18 12:52:06,369+02 WARN  [org.ovirt.engine.core.bll.storage.disk.image.ImagesHandler] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] Unable to tear down image: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to TeardownImageVDS, error = Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',) (Failed with error CannotDeactivateLogicalVolume and code 552)
        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.storage.disk.image.ImagesHandler.teardownImage(ImagesHandler.java:1019) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.ImagesHandler.getQemuImageInfoFromVdsm(ImagesHandler.java:860) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.BaseImagesCommand.setQcowCompat(BaseImagesCommand.java:432) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.BaseImagesCommand.setQcowCompatByQemuImageInfo(BaseImagesCommand.java:416) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.BaseImagesCommand.endSuccessfully(BaseImagesCommand.java:369) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:736) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:694) [bll.jar:]


VDSM:
2017-11-18 12:52:06,354+0200 DEBUG (jsonrpc/3) [storage.Misc.excCmd] FAILED: <err> = '  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\n  Logical volume abfe1fa0-ba
8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\n  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\n'; <rc> = 5 (commands:93)
2017-11-18 12:52:06,354+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/99
29e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf
-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',) fr
om=::ffff:10.35.69.166,39648, flow_id=snapshots_create_fb1020a3-5674-4263, task_id=a062e828-1fba-4dae-97ff-2847458aefc9 (api:50)
2017-11-18 12:52:06,355+0200 ERROR (jsonrpc/3) [storage.TaskManager.Task] (Task='a062e828-1fba-4dae-97ff-2847458aefc9') Unexpected error (task:872)
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 879, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in teardownImage
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 3189, in teardownImage
    dom.deactivateImage(imgUUID)
  File "/usr/share/vdsm/storage/blockSD.py", line 1289, in deactivateImage
    lvm.deactivateLVs(self.sdUUID, volUUIDs)
  File "/usr/share/vdsm/storage/lvm.py", line 1304, in deactivateLVs
    _setLVAvailability(vgName, toDeactivate, "n")
  File "/usr/share/vdsm/storage/lvm.py", line 843, in _setLVAvailability
    raise error(str(e))
CannotDeactivateLogicalVolume: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',)
2017-11-18 12:52:06,356+0200 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='a062e828-1fba-4dae-97ff-2847458aefc9') Task._run: a062e828-1fba-4dae-97ff-2847458aefc9 ('abfe1fa0-ba8a-48f7-845f-0e7902b37c8b', '55c08989-8631-4fe1-8aae-5c4c7217eba7', 'fca18a71-15ef-4740-a7f7-ce414f34624a', None) {} failed - stopping task (task:891)
2017-11-18 12:52:06,356+0200 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='a062e828-1fba-4dae-97ff-2847458aefc9') stopping in state preparing (force False) (task:1252)
2017-11-18 12:52:06,357+0200 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='a062e828-1fba-4dae-97ff-2847458aefc9') ref 1 aborting True (task:999)
2017-11-18 12:52:06,357+0200 INFO  (jsonrpc/3) [storage.TaskManager.Task] (Task='a062e828-1fba-4dae-97ff-2847458aefc9') aborting: Task is aborted: 'Cannot deactivate Logical Volume: (\'General Storage Exception: ("5 [] [\\\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\\\', \\\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\\\', \\\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\\\']\\\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\\\'f6c436bf-16da-40ba-83aa-3086bad8c814\\\', \\\'9929e32e-80e3-450f-8696-691154ce480e\\\', \\\'0b2ece94-88b3-4620-8d3e-37270701f60d\\\']",)\',)' - code 552 (task:1177)
2017-11-18 12:52:06,357+0200 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='a062e828-1fba-4dae-97ff-2847458aefc9') Prepare: aborted: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',) (task:1182)

Comment 2 Allon Mureinik 2017-11-19 11:16:59 UTC
Raz - other than an ugly message in the VM log, what is the functional impact? I wonder if it's worth the hassle/risk to backport it to 4.1.

Tentatively targetted to 4.1.8 - either we decide to backport the fix from 4.2, or just close this as a duplicate, as its fixed in 4.2.

Comment 3 Raz Tamir 2017-11-19 11:32:24 UTC
(In reply to Allon Mureinik from comment #2)
> Raz - other than an ugly message in the VM log, what is the functional
> impact? I wonder if it's worth the hassle/risk to backport it to 4.1.

Creation of live snapshot is failing
> 
> Tentatively targetted to 4.1.8 - either we decide to backport the fix from
> 4.2, or just close this as a duplicate, as its fixed in 4.2.

Comment 4 Ala Hino 2017-11-19 18:39:25 UTC
Raz,

Which snapshot failed to be created?

Although the error appears in the log, I don't see create snapshots that failed.

Usually, 'Failed to complete snapshot' is the message that I look for when snapshot creation fails, and 'creation for VM '${VmName}' has been completed' when snapshot creation succeeds.

Comment 5 Raz Tamir 2017-11-19 19:05:58 UTC
(In reply to Ala Hino from comment #4)
> Raz,
> 
> Which snapshot failed to be created?
Auto-generated snapshot of LSM
> 
> Although the error appears in the log, I don't see create snapshots that
> failed.
> 
> Usually, 'Failed to complete snapshot' is the message that I look for when
> snapshot creation fails, and 'creation for VM '${VmName}' has been
> completed' when snapshot creation succeeds.

Comment 6 Ala Hino 2017-11-19 20:01:46 UTC
I don't see failure in creating any snapshot:


=====
2017-11-18 12:53:42,545+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-28) [disks_syncAction_39563b69-4027-4a5d] EVENT_ID: USER_CREATE_SNAPSHOT(45), Correlation ID: disks_syncAction_39563b69-4027-4a5d, Job ID: 2d6e4faf-5e2d-4691-aceb-a6022e5bdda4, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase6057_REST_ISCSI_1812471736' was initiated by admin@internal-authz.

2017-11-18 12:53:52,837+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler5) [] EVENT_ID: USER_CREATE_SNAPSHOT_FINISHED_SUCCESS(68), Correlation ID: disks_syncAction_39563b69-4027-4a5d, Job ID: 2d6e4faf-5e2d-4691-aceb-a6022e5bdda4, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase6057_REST_ISCSI_1812471736' has been completed.
=====
2017-11-18 13:03:03,345+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-9) [disks_syncAction_89898bed-2c05-48fa] EVENT_ID: USER_CREATE_SNAPSHOT(45), Correlation ID: disks_syncAction_89898bed-2c05-48fa, Job ID: fc5e6d32-40d2-41ee-b518-48cee956c9a8, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase6057_REST_ISCSI_1812471736' was initiated by admin@internal-authz.

2017-11-18 13:03:13,291+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [] EVENT_ID: USER_CREATE_SNAPSHOT_FINISHED_SUCCESS(68), Correlation ID: disks_syncAction_89898bed-2c05-48fa, Job ID: fc5e6d32-40d2-41ee-b518-48cee956c9a8, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase6057_REST_ISCSI_1812471736' has been completed.
=====
2017-11-18 13:06:10,293+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-27) [disks_syncAction_94052c04-c25a-4807] EVENT_ID: USER_CREATE_SNAPSHOT(45), Correlation ID: disks_syncAction_94052c04-c25a-4807, Job ID: 395fe3eb-d68e-4dc6-a647-2cae88a92276, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase6057_REST_ISCSI_1812471736' was initiated by admin@internal-authz.

2017-11-18 13:06:27,677+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler2) [] EVENT_ID: USER_CREATE_SNAPSHOT_FINISHED_SUCCESS(68), Correlation ID: disks_syncAction_94052c04-c25a-4807, Job ID: 395fe3eb-d68e-4dc6-a647-2cae88a92276, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Snapshot 'Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase6057_REST_ISCSI_1812471736' has been completed.
=====

3 Auto-generated snapshots successfully created.

How/where do you see the one that failed?

Comment 7 Raz Tamir 2017-11-19 20:41:38 UTC
I'll try to explain what I debug here.
The operation that failed is teardown image that close the create snapshot operation - lvchange -a n

It starts here (vdsm.log):
2017-11-18 12:51:37,289+0200 INFO  (jsonrpc/3) [storage.LVM] Deactivating lvs: vg=abfe1fa0-ba8a-48f7-845f-0e7902b37c8b lvs=['f6c436bf-16da-40ba-83aa-3086bad8c814', '9929e32e-80e3-450f-8696-691154ce480e', '0b2ece94-
88b3-4620-8d3e-37270701f60d'] (lvm:1303)

And first failed here (vdsm.log):
2017-11-18 12:51:51,799+0200 DEBUG (jsonrpc/3) [storage.Misc.excCmd] FAILED: <err> = '  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\n  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\n  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\n'; <rc> = 5 (commands:93)


And following with the exception (vds,.log):
2017-11-18 12:52:06,354+0200 DEBUG (jsonrpc/3) [storage.Misc.excCmd] FAILED: <err> = '  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\n  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\n  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\n'; <rc> = 5 (commands:93)
2017-11-18 12:52:06,354+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',) from=::ffff:10.35.69.166,39648, flow_id=snapshots_create_fb1020a3-5674-4263, task_id=a062e828-1fba-4dae-97ff-2847458aefc9 (api:50)
2017-11-18 12:52:06,355+0200 ERROR (jsonrpc/3) [storage.TaskManager.Task] (Task='a062e828-1fba-4dae-97ff-2847458aefc9') Unexpected error (task:872)
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 879, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in teardownImage
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 3189, in teardownImage
    dom.deactivateImage(imgUUID)
  File "/usr/share/vdsm/storage/blockSD.py", line 1289, in deactivateImage
    lvm.deactivateLVs(self.sdUUID, volUUIDs)
  File "/usr/share/vdsm/storage/lvm.py", line 1304, in deactivateLVs
    _setLVAvailability(vgName, toDeactivate, "n")
  File "/usr/share/vdsm/storage/lvm.py", line 843, in _setLVAvailability
    raise error(str(e))
CannotDeactivateLogicalVolume: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',)



The call for create snapshot (in our automation):
2017-11-18 12:51:04,874 - MainThread - snapshots - DEBUG - CREATE request content is --  url:/ovirt-engine/api/vms/527c311c-264a-4992-87c6-b611c382ac96/snapshots body:<snapshot>
    <description>snapshot_6057_iscsi_1</description>
</snapshot>
 
2017-11-18 12:51:04,874 - MainThread - snapshots - INFO - Using Correlation-Id: snapshots_create_fb1020a3-5674-4263

From that correlation-id (snapshots_create_fb1020a3-5674-4263):

2017-11-18 12:51:36,281+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] START, PrepareImageVDSCommand(HostName = host_mixe
d_2, PrepareImageVDSCommandParameters:{runAsync='true', hostId='5ae36066-4b80-4f31-a8c0-bb67ed2004da'}), log id: 68646ddf
2017-11-18 12:51:37,070+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.PrepareImageVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] FINISH, PrepareImageVDSCommand, return: PrepareIma
geReturn:{status='Status [code=0, message=Done]'}, log id: 68646ddf
2017-11-18 12:51:37,071+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetQemuImageInfoVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] START, GetQemuImageInfoVDSCommand(HostName = h
ost_mixed_2, GetVolumeInfoVDSCommandParameters:{runAsync='true', hostId='5ae36066-4b80-4f31-a8c0-bb67ed2004da', storagePoolId='55c08989-8631-4fe1-8aae-5c4c7217eba7', storageDomainId='abfe1fa0-ba8a-48f7-845f-0e7902b
37c8b', imageGroupId='fca18a71-15ef-4740-a7f7-ce414f34624a', imageId='f6c436bf-16da-40ba-83aa-3086bad8c814'}), log id: 3b493c1e
2017-11-18 12:51:37,173+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetQemuImageInfoVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] FINISH, GetQemuImageInfoVDSCommand, return: or
g.ovirt.engine.core.common.businessentities.storage.QemuImageInfo@491b8a3c, log id: 3b493c1e
2017-11-18 12:51:37,175+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] START, TeardownImageVDSCommand(HostName = host_mi
xed_2, ImageActionsVDSCommandParameters:{runAsync='true', hostId='5ae36066-4b80-4f31-a8c0-bb67ed2004da'}), log id: 743649a1
2017-11-18 12:51:47,223+02 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler9) [7a1c1631] VM '527c311c-264a-4992-87c6-b611c382ac96'(vm_TestCase6057_REST_ISCSI_1812471736) moved f
rom 'Paused' --> 'Up'
2017-11-18 12:51:47,230+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler9) [7a1c1631] START, FullListVDSCommand(HostName = host_mixed_2, FullListVDSCommandParameters:{
runAsync='true', hostId='5ae36066-4b80-4f31-a8c0-bb67ed2004da', vmIds='[527c311c-264a-4992-87c6-b611c382ac96]'}), log id: 6c587728
2017-11-18 12:51:47,831+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler9) [7a1c1631] FINISH, FullListVDSCommand, return: [{acpiEnable=true, emulatedMachine=pc-i440fx-
rhel7.3.0, vmId=527c311c-264a-4992-87c6-b611c382ac96, guestDiskMapping={2a1f359c-c812-432f-b={name=/dev/vda}, QEMU_DVD-ROM_QM00003={name=/dev/sr0}}, transparentHugePages=true, timeOffset=0, cpuType=Conroe, smp=1, p
auseCode=NOERR, guestNumaNodes=[Ljava.lang.Object;@2f42b01a, smartcardEnable=false, custom={}, vmType=kvm, memSize=1024, smpCoresPerSocket=1, vmName=vm_TestCase6057_REST_ISCSI_1812471736, nice=0, status=Up, maxMemS
ize=4096, bootMenuEnable=false, pid=81152, smpThreadsPerCore=1, memGuaranteedSize=1024, kvmEnable=true, pitReinjection=false, displayNetwork=ovirtmgmt, devices=[Ljava.lang.Object;@d599ba9, display=qxl, maxVCpus=16,
 clientIp=, statusTime=4364322200, maxMemSlots=16}], log id: 6c587728
2017-11-18 12:51:47,833+02 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler9) [7a1c1631] Received a spice Device without an address when processing VM 527c311c-264a-499
2-87c6-b611c382ac96 devices, skipping device: {device=spice, specParams={fileTransferEnable=true, displayNetwork=ovirtmgmt, copyPasteEnable=true, displayIp=10.35.66.7, spiceSecureChannels=smain,sinputs,scursor,spla
yback,srecord,sdisplay,ssmartcard,susbredir}, type=graphics, deviceId=af456dc1-ac34-4a95-885e-55a98dd8d2c7, tlsPort=5900}
2017-11-18 12:52:06,369+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] 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_2 command TeardownImageVDS failed: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  L
ogical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical
 volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\
', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',)
2017-11-18 12:52:06,369+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] Command 'TeardownImageVDSCommand(HostName = host_
mixed_2, ImageActionsVDSCommandParameters:{runAsync='true', hostId='5ae36066-4b80-4f31-a8c0-bb67ed2004da'})' execution failed: VDSGenericException: VDSErrorException: Failed in vdscommand to TeardownImageVDS, error
 = Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f
7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'
f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',)
2017-11-18 12:52:06,369+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] FINISH, TeardownImageVDSCommand, log id: 743649a1
2017-11-18 12:52:06,369+02 WARN  [org.ovirt.engine.core.bll.storage.disk.image.ImagesHandler] (DefaultQuartzScheduler2) [snapshots_create_fb1020a3-5674-4263] Unable to tear down image: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to TeardownImageVDS, error = Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/9929e32e-80e3-450f-8696-691154ce480e in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/0b2ece94-88b3-4620-8d3e-37270701f60d in use.\', \'  Logical volume abfe1fa0-ba8a-48f7-845f-0e7902b37c8b/f6c436bf-16da-40ba-83aa-3086bad8c814 in use.\']\\nabfe1fa0-ba8a-48f7-845f-0e7902b37c8b/[\'f6c436bf-16da-40ba-83aa-3086bad8c814\', \'9929e32e-80e3-450f-8696-691154ce480e\', \'0b2ece94-88b3-4620-8d3e-37270701f60d\']",)',) (Failed with error CannotDeactivateLogicalVolume and code 552)

Comment 8 Ala Hino 2017-11-19 20:48:14 UTC
The thing is that CannotDeactivateLogicalVolume is handled by the engine (despite the stack trace seen in the log). This error doesn't fail the snapshot creation.

How do you check that snapshot creation failed?

BTW, if creation the auto-generated snapshot failed, I'd expect all LSM operation to fail. Did LSM fail?

BTW2, this one seems exactly as BZ 1510957. In that bug, the error was there but snapshot creation did succeed. Isn't this one the same?

Comment 9 Raz Tamir 2017-11-19 20:52:33 UTC
(In reply to Ala Hino from comment #8)
> The thing is that CannotDeactivateLogicalVolume is handled by the engine
> (despite the stack trace seen in the log). This error doesn't fail the
> snapshot creation.
> 
> How do you check that snapshot creation failed?
ok, this is my mistake, the snapshot itself created but the entire creation flow didn't
> 
> BTW, if creation the auto-generated snapshot failed, I'd expect all LSM
> operation to fail. Did LSM fail?
No
> 
> BTW2, this one seems exactly as BZ 1510957. In that bug, the error was there
> but snapshot creation did succeed. Isn't this one the same?
Yes, exactly the same error code 552

Comment 10 Ala Hino 2017-11-19 20:56:26 UTC
(In reply to Raz Tamir from comment #9)
> (In reply to Ala Hino from comment #8)
> > The thing is that CannotDeactivateLogicalVolume is handled by the engine
> > (despite the stack trace seen in the log). This error doesn't fail the
> > snapshot creation.
> > 
> > How do you check that snapshot creation failed?
> ok, this is my mistake, the snapshot itself created but the entire creation
> flow didn't
> > 
> > BTW, if creation the auto-generated snapshot failed, I'd expect all LSM
> > operation to fail. Did LSM fail?
> No
> > 
> > BTW2, this one seems exactly as BZ 1510957. In that bug, the error was there
> > but snapshot creation did succeed. Isn't this one the same?
> Yes, exactly the same error code 552

Can you please explain what do you mean by the entire flow? Did you expect to see something that you don't see now?

Based on the code, the error seen here occurs at the very last step of snapshot creation (setting qcow compat), and this happens when the snapshot successfully created (code wise).

Comment 11 Raz Tamir 2017-11-19 21:01:50 UTC
(In reply to Ala Hino from comment #10)
> (In reply to Raz Tamir from comment #9)
> > (In reply to Ala Hino from comment #8)
> > > The thing is that CannotDeactivateLogicalVolume is handled by the engine
> > > (despite the stack trace seen in the log). This error doesn't fail the
> > > snapshot creation.
> > > 
> > > How do you check that snapshot creation failed?
> > ok, this is my mistake, the snapshot itself created but the entire creation
> > flow didn't
> > > 
> > > BTW, if creation the auto-generated snapshot failed, I'd expect all LSM
> > > operation to fail. Did LSM fail?
> > No
> > > 
> > > BTW2, this one seems exactly as BZ 1510957. In that bug, the error was there
> > > but snapshot creation did succeed. Isn't this one the same?
> > Yes, exactly the same error code 552
> 
> Can you please explain what do you mean by the entire flow? Did you expect
> to see something that you don't see now?
> 
> Based on the code, the error seen here occurs at the very last step of
> snapshot creation (setting qcow compat), and this happens when the snapshot
> successfully created (code wise).

This is what I expected to see - that the flow finished successfully (I think the operation that failed is to teardown the image to be able to set the qcow compat)

Comment 12 Ala Hino 2017-11-19 21:15:08 UTC
(In reply to Raz Tamir from comment #11)
> (In reply to Ala Hino from comment #10)
> > (In reply to Raz Tamir from comment #9)
> > > (In reply to Ala Hino from comment #8)
> > > > The thing is that CannotDeactivateLogicalVolume is handled by the engine
> > > > (despite the stack trace seen in the log). This error doesn't fail the
> > > > snapshot creation.
> > > > 
> > > > How do you check that snapshot creation failed?
> > > ok, this is my mistake, the snapshot itself created but the entire creation
> > > flow didn't
> > > > 
> > > > BTW, if creation the auto-generated snapshot failed, I'd expect all LSM
> > > > operation to fail. Did LSM fail?
> > > No
> > > > 
> > > > BTW2, this one seems exactly as BZ 1510957. In that bug, the error was there
> > > > but snapshot creation did succeed. Isn't this one the same?
> > > Yes, exactly the same error code 552
> > 
> > Can you please explain what do you mean by the entire flow? Did you expect
> > to see something that you don't see now?
> > 
> > Based on the code, the error seen here occurs at the very last step of
> > snapshot creation (setting qcow compat), and this happens when the snapshot
> > successfully created (code wise).
> 
> This is what I expected to see - that the flow finished successfully (I
> think the operation that failed is to teardown the image to be able to set
> the qcow compat)

I am probably missing something.
Tear down is an "internal" step that is needed when setting qcow compat during creating snapshots while the VM is down. Same for prepare image. 

Sometimes, the VM is paused during snapshot creation, if at the time the flow reach the point to set the qcow compat (the behavior we see here), we mistakenly try to prepare and teardown the image. Although this is wrong, it doesn't fail the flow.

In any case, I will backport the master patch so we don't see this error anymore.

Comment 13 Raz Tamir 2017-11-26 09:55:46 UTC
Verified based on automation run - ovirt-engine-4.1.8.1-0.1.el7.noarch

Comment 14 Tal Nisan 2018-01-09 15:55:48 UTC
*** Bug 1532464 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.