Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1583046

Summary: [Blocked] Disk deactivation (and hot-unplug) fails ("Conflict") messsage - if it is done too quick after accessing it from the VM
Product: Red Hat Enterprise Virtualization Manager Reporter: Marcin <m.kubacki>
Component: ovirt-engineAssignee: Eyal Shenitzky <eshenitz>
Status: CLOSED DEFERRED QA Contact: Avihai <aefrat>
Severity: medium Docs Contact:
Priority: unspecified    
Version: unspecifiedCC: lsurette, m.kubacki, srevivo, tnisan
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: All   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-09-29 11:33:06 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1588461, 1589749    
Bug Blocks:    
Attachments:
Description Flags
RHV logs
none
Earlier log none

Description Marcin 2018-05-28 07:08:23 UTC
Created attachment 1442739 [details]
RHV logs

Description of problem:
We want deactivate and detach drives, and in significant number of cases (around 40%) we cannot deactivate/detach drive from our VM.
The message ("Conflict") doesn’t explain anything, cause we would expect oVirt to deactivate and detach all. 

We use ovirt-engine SDK for Java (4.2.1).

When executing disk deactivation (and later hot-unplug) using the API, API reports "Conflict" as an error message.
We don’t why user is later able to successfully detach drives from our Proxy VM, while we can’t do that and we receive messages like this (full logs attached - important piece is around 2018-05-18 17:05):

2018-05-18 17:05:22,436+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-26) [2314a1eb-7115-4b9a-afb2-e228d7ac1196] FINISH, HotUnPlugDiskVDSCommand, log id: 726ea439
2018-05-18 17:05:22,457+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-26) [2314a1eb-7115-4b9a-afb2-e228d7ac1196] EVENT_ID: USER_HOTUNPLUG_DISK(2,002), VM vProtect disk proxy02_Disk1 was unplugged by admin@internal.
2018-05-18 17:05:22,458+02 INFO  [org.ovirt.engine.core.bll.storage.disk.HotUnPlugDiskFromVmCommand] (default task-26) [2314a1eb-7115-4b9a-afb2-e228d7ac1196] Lock freed to object 'EngineLock:{exclusiveLocks='[65695857-6c7a-44d7-8b6c-0a8cc0833e10=DISK]', sharedLocks='[c2945db4-badc-4805-8765-0e9c7152a224=VM]'}'
2018-05-18 17:05:22,629+02 INFO  [org.ovirt.engine.core.bll.storage.disk.UpdateVmDiskCommand] (default task-26) [2314a1eb-7115-4b9a-afb2-e228d7ac1196] Lock Acquired to object 'EngineLock:{exclusiveLocks='', sharedLocks='[c896e7a3-8826-4c5e-833f-717620c3aa7c=VM]'}'
2018-05-18 17:05:22,664+02 INFO  [org.ovirt.engine.core.bll.storage.disk.UpdateVmDiskCommand] (default task-26) [2314a1eb-7115-4b9a-afb2-e228d7ac1196] Running command: UpdateVmDiskCommand internal: false. Entities affected :  ID: 65695857-6c7a-44d7-8b6c-0a8cc0833e10 Type: DiskAction group EDIT_DISK_PROPERTIES with role type USER
2018-05-18 17:05:22,724+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.AmendImageGroupVolumesCommand] (default task-26) [18c2cad3] Lock Acquired to object 'EngineLock:{exclusiveLocks='[65695857-6c7a-44d7-8b6c-0a8cc0833e10=DISK]', sharedLocks='[c2945db4-badc-4805-8765-0e9c7152a224=VM, c896e7a3-8826-4c5e-833f-717620c3aa7c=VM]'}'
2018-05-18 17:05:22,729+02 WARN  [org.ovirt.engine.core.bll.storage.disk.image.AmendImageGroupVolumesCommand] (default task-26) [18c2cad3] Validation of action 'AmendImageGroupVolumes' failed for user admin@internal. Reasons: VAR__ACTION__AMEND,VAR__TYPE__DISK,ACTION_TYPE_FAILED_DISK_PLUGGED_TO_NON_DOWN_VMS,$DiskName proxy02_Disk1,$VmList proxy02
2018-05-18 17:05:22,730+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.AmendImageGroupVolumesCommand] (default task-26) [18c2cad3] Lock freed to object 'EngineLock:{exclusiveLocks='[65695857-6c7a-44d7-8b6c-0a8cc0833e10=DISK]', sharedLocks='[c2945db4-badc-4805-8765-0e9c7152a224=VM, c896e7a3-8826-4c5e-833f-717620c3aa7c=VM]'}'
2018-05-18 17:05:22,730+02 INFO  [org.ovirt.engine.core.bll.storage.disk.UpdateVmDiskCommand] (default task-26) [18c2cad3] Lock freed to object 'EngineLock:{exclusiveLocks='', sharedLocks='[c896e7a3-8826-4c5e-833f-717620c3aa7c=VM]'}'
2018-05-18 17:05:22,743+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-26) [18c2cad3] EVENT_ID: USER_FAILED_UPDATE_VM_DISK(89), Failed to update VM vProtect disk proxy02_Disk1 (User: admin@internal).
2018-05-18 17:05:22,744+02 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-26) [] Operation Failed: [Cannot amend Virtual Disk. The disk proxy02_Disk1 is plugged to non-Down VMs: proxy02]
2018-05-18 17:05:22,773+02 INFO  [org.ovirt.engine.core.sso.servlets.OAuthRevokeServlet] (default task-47) [] User admin@internal successfully logged out
2018-05-18 17:05:22,789+02 INFO  [org.ovirt.engine.core.bll.aaa.TerminateSessionsForTokenCommand] (default task-39) [25107868] Running command: TerminateSessionsForTokenCommand internal: true.
2018-05-18 17:05:23,116+02 INFO  [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-22) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access
2018-05-18 17:05:23,154+02 INFO  [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-30) [53dd98fd] Running command: CreateUserSessionCommand internal: false.
2018-05-18 17:05:23,165+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-30) [53dd98fd] EVENT_ID: USER_VDC_LOGIN(30), User admin@internal connecting from '10.80.53.81' using session 'CF2Orpp5MIy9+pG9Oh11oLYi04l8OwkYEnt20qnAejjRXd1Prh3WrMlLZdpD9orGKbLiRbmJaHjg6x8eAixY1w==' logged in.
2018-05-18 17:05:23,529+02 INFO  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (default task-30) [63351c79-8860-4437-9be3-17002750ecee] Lock Acquired to object 'EngineLock:{exclusiveLocks='[c896e7a3-8826-4c5e-833f-717620c3aa7c=VM]', sharedLocks=''}'
2018-05-18 17:05:23,550+02 WARN  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (default task-30) [63351c79-8860-4437-9be3-17002750ecee] Validation of action 'RemoveSnapshot' failed for user admin@internal. Reasons: VAR__TYPE__SNAPSHOT,VAR__ACTION__REMOVE,ACTION_TYPE_FAILED_VM_DISK_SNAPSHOT_IS_ATTACHED_TO_ANOTHER_VM,$disksInfo proxy02_Disk1 ,vProtect backup 2018-05-18 16:44:51.692, vProtect
2018-05-18 17:05:23,551+02 INFO  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (default task-30) [63351c79-8860-4437-9be3-17002750ecee] Lock freed to object 'EngineLock:{exclusiveLocks='[c896e7a3-8826-4c5e-833f-717620c3aa7c=VM]', sharedLocks=''}'
2018-05-18 17:05:23,560+02 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-30) [] Operation Failed: [Cannot remove Snapshot. The following VM's disks snapshots are attached to other VMs (Disk Alias/Snapshot Description/VM attached to):

 proxy02_Disk1 ,vProtect backup 2018-05-18 16:44:51.692, vProtect 

Please detach them from those VMs and try again.]

Version-Release number of selected component (if applicable):
4.2.3

How reproducible:
- around 40% cases


Steps to Reproduce:

Try with several threads simultaneously
1. Attach drive
2. Read data
3. Deactivate drive
- here is "Conflict"
4. Detach drive
- here also "Conflict" can occur

Wait a while and try to deactivate and detach drive manually - it will succeed.

Actual results:
- Quite often "Conflict" error returned

Expected results:
- Successful Deactivation

Additional info:
-

Comment 2 Maor 2018-05-28 08:29:18 UTC
Hi Marcin,

Can you please also attach the REST request which you sent (assuming you are using REST/SDK scripts to hot unplug and detach the disks)
It seems like you first try to update the disk and amend it.

Comment 3 Marcin 2018-05-28 08:57:24 UTC
Sure - we use SDK not API directly.

We're waiting for disk to UNLOCK based on its status and
later send deactivation reequest. "active" variable is false.

waitForDiskUnlock(diskId, c);
final boolean active = false;
attachmentService.update().diskAttachment(
                    diskAttachment()
                            .id(attachment.id())
                            .active(active))
                    .send().diskAttachment();

Comment 4 Eyal Shenitzky 2018-05-28 09:26:58 UTC
Hey Marcin,

The engine log that attached does not contain the relevant log that you mentioned in the bug description, can you please add the relevant log?

Also, can you please add more specific steps to reproduce (e.g if you take a snapshot of the VM, is the VM running while you attach the disk, what was the disk type file/block, ...)

Comment 5 Marcin 2018-05-28 09:34:15 UTC
Created attachment 1443073 [details]
Earlier log

Comment 6 Eyal Shenitzky 2018-05-28 09:46:29 UTC
(In reply to Eyal Shenitzky from comment #4)
> Hey Marcin,
> 
> The engine log that attached does not contain the relevant log that you
> mentioned in the bug description, can you please add the relevant log?
> 
> Also, can you please add more specific steps to reproduce (e.g if you take a
> snapshot of the VM, is the VM running while you attach the disk, what was
> the disk type file/block, ...)

Can you please add the full steps to reproduce?

Comment 7 Marcin 2018-05-28 10:00:10 UTC
1. We take snapshot of a VM (it is running, disks are QCOw2-based)

        Snapshot snapshot = c.getSnapshotsSvc(vmId).add().snapshot(
                snapshot().description(snapshotDescription)
                        .persistMemorystate(false))
                .send().snapshot();
        return waitForSnapshotCreate(snapshot.id(), vmId, timeout);

2. Attach disk snapshots to our Proxy VM

        DiskBuilder diskBuilder = disk().id(diskId);
        if (snapshotId != null) {
            diskBuilder.snapshot(snapshot().id(snapshotId));
        }
        DiskAttachment attachment = c.getDiskAttachmentsSvc(vmId).add().attachment(
                diskAttachment().disk(diskBuilder)
                        .active(true)
                        .bootable(bootable)
                        .interface_(diskInterface))
                .send().attachment();

3. Dump data from proxy

4. We try to deactivate disk

        c.getDiskAttachmentSvc(attachment.id(), vmId)
                .remove().detachOnly(true).send();

5. we receive "Conflict" just when we invoke send() in the above-mentioned code

It doesn't happen always - most probable when multiple attach/detach operations happen at once.

Comment 8 Eyal Shenitzky 2018-05-28 10:16:38 UTC
In the log, we can see that the disk was updated and amended.
Did you try to update the disk?
Is there was another thread that tried to do is simultaneously on the same snapshot disks?

Comment 9 Marcin 2018-05-28 10:26:23 UTC
No - only one thread is accessing it.

From SDK perspective - we don't have anything related to "amend". Maybe this "update" is a result of our "deactivate" action.

Comment 10 Eyal Shenitzky 2018-05-31 06:09:02 UTC
This are the specific steps to reproduce:

1. Create a VM [VM1] with disk
2. Create a snapshot to VM1
3. Create another VM [VM2] with disk
4. Attach the snapshot disk created in step 2 to VM2
5. Run VM2
6. Using REST-API, hot-unplug the snapshot disk attached to VM2

* also failed when trying to edit the snapshot disk that attached to VM2 vi the UI

Comment 11 Eyal Shenitzky 2018-05-31 11:39:26 UTC
Marcin, I failed to reproduce this issue via REST-API,
Can you please supply more details on your environment, is this an upgraded environment? did you try any other operation on the VM/disk while that snapshot disk was attached to the VM?

Comment 12 Eyal Shenitzky 2018-05-31 11:41:27 UTC
Because the issue doesn't reproduce in the REST-API only via the UI, I restore the old bug description.

Comment 13 Marcin 2018-05-31 20:00:17 UTC
Eyal, we are using SDK for Java (4.2.1), and the REST calls are hidden from us. And it doesn't happen always, but I guess if RHV enviornment is simultaneously attaching and detaching disks, we end up quite often in this Conflict error. 

RHV: 4.2.3.8-0.1.el7

"Conflict" message happens sometimes in other moments, like snapshot removal (even in old API and 3.x oVirt/RHV). Simple retry after some time was in general the right way to get rid of the snapshots, but in general it looks like RHV does some internal processing and our calls happen maybe too fast, which causes "conflict". And even when we've been waiting on "Locked" flags (on VMs/Clones/Snapshots etc.) - it still was sometimes reported as "OK" (= not locked), we proceeded with snapshot removals (or like in this bug, with deactivation), but eventually we still end-up with "Conflict".

Comment 14 Yaniv Kaul 2018-06-01 20:44:59 UTC
(In reply to Marcin from comment #13)
> Eyal, we are using SDK for Java (4.2.1), and the REST calls are hidden from
> us. And it doesn't happen always, but I guess if RHV enviornment is
> simultaneously attaching and detaching disks, we end up quite often in this
> Conflict error. 

You could see the REST API calls @ /var/log/httpd/ovirt-requests-log on the Engine.

> 
> RHV: 4.2.3.8-0.1.el7
> 
> "Conflict" message happens sometimes in other moments, like snapshot removal
> (even in old API and 3.x oVirt/RHV). Simple retry after some time was in
> general the right way to get rid of the snapshots, but in general it looks
> like RHV does some internal processing and our calls happen maybe too fast,
> which causes "conflict". And even when we've been waiting on "Locked" flags
> (on VMs/Clones/Snapshots etc.) - it still was sometimes reported as "OK" (=
> not locked), we proceeded with snapshot removals (or like in this bug, with
> deactivation), but eventually we still end-up with "Conflict".

Comment 15 Eyal Shenitzky 2018-06-03 06:07:34 UTC
(In reply to Marcin from comment #3)
> Sure - we use SDK not API directly.
> 
> We're waiting for disk to UNLOCK based on its status and
> later send deactivation reequest. "active" variable is false.
> 
> waitForDiskUnlock(diskId, c);
> final boolean active = false;
> attachmentService.update().diskAttachment(
>                     diskAttachment()
>                             .id(attachment.id())
>                             .active(active))
>                     .send().diskAttachment();

In the comment above you really 'deactivate' the snapshot disk.

(In reply to Marcin from comment #7)
> 1. We take snapshot of a VM (it is running, disks are QCOw2-based)
> 
>         Snapshot snapshot = c.getSnapshotsSvc(vmId).add().snapshot(
>                 snapshot().description(snapshotDescription)
>                         .persistMemorystate(false))
>                 .send().snapshot();
>         return waitForSnapshotCreate(snapshot.id(), vmId, timeout);
> 
> 2. Attach disk snapshots to our Proxy VM
> 
>         DiskBuilder diskBuilder = disk().id(diskId);
>         if (snapshotId != null) {
>             diskBuilder.snapshot(snapshot().id(snapshotId));
>         }
>         DiskAttachment attachment =
> c.getDiskAttachmentsSvc(vmId).add().attachment(
>                 diskAttachment().disk(diskBuilder)
>                         .active(true)
>                         .bootable(bootable)
>                         .interface_(diskInterface))
>                 .send().attachment();
> 
> 3. Dump data from proxy
> 
> 4. We try to deactivate disk
> 
>         c.getDiskAttachmentSvc(attachment.id(), vmId)
>                 .remove().detachOnly(true).send();
> 
> 5. we receive "Conflict" just when we invoke send() in the above-mentioned
> code
> 
> It doesn't happen always - most probable when multiple attach/detach
> operations happen at once.

But in step 4 in this comment you used the remove action with detachOnly=true, this operation will cause the snapshot disk to detach from the VM.
Maybe there is a 'conflict' because you are trying to detach the disk twice?

Comment 16 Marcin 2018-06-04 13:35:10 UTC
No chance:
1. request to deactivate
2. wait 1 minute and check periodically status (or like in our case - we receive "Conflict" exception in the request inself)
3. repeat several times 1. and 2. - if "Conflict" or minute has gone off.

Comment 17 Eyal Shenitzky 2018-06-06 11:27:19 UTC
(In reply to Marcin from comment #16)
> No chance:
> 1. request to deactivate
> 2. wait 1 minute and check periodically status (or like in our case - we
> receive "Conflict" exception in the request inself)
> 3. repeat several times 1. and 2. - if "Conflict" or minute has gone off.

So in which call are you using in the script?

c.getDiskAttachmentSvc(attachment.id(), vmId)
                .remove().detachOnly(true).send();

or - 

waitForDiskUnlock(diskId, c);
final boolean active = false;
attachmentService.update().diskAttachment(
                    diskAttachment()
                            .id(attachment.id())
                            .active(active))
                    .send().diskAttachment();

Comment 18 Marcin 2018-06-06 12:40:52 UTC
In the 1st step - more precisely: we first try to deactivate disk and only if it succeeded we try to detach. But we end up quite frequently with the problem with deactivate call - it resultts in exception, so we have to catch it check if it is "Conflict" and try to repeat. Next time we usually are more successful with deactivation and detachment.

Comment 19 Eyal Shenitzky 2018-06-07 08:09:18 UTC
OK, so the steps are in the following order?

1) c.getDiskAttachmentSvc(attachment.id(), vmId)
                .remove().detachOnly(true).send();

2) waitForDiskUnlock(diskId, c);
final boolean active = false;
attachmentService.update().diskAttachment(
                    diskAttachment()
                            .id(attachment.id())
                            .active(active))
                    .send().diskAttachment();

If so, the first command detach the disk from the VM but not remove it (the disk is now 'floating' disk and not attached to any VM)
And the second command really tries to deactivate the un-attached disk

Comment 20 Marcin 2018-06-07 08:43:20 UTC
The opposite - you can't detach active disk. So we first try to deactivate disk and this throws "Conflict". Then we retry after a while and it succeeds.

Comment 21 Eyal Shenitzky 2018-06-07 08:59:23 UTC
And why you are waiting for the disk to unlock?
What it the operation that previous to the disk deactivation?

Comment 22 Marcin 2018-06-07 09:22:31 UTC
Just data export. This is just to make sure that disk is in OK status before proceeding with deactivation. Otherwise we could get conflict anyway.

Comment 23 Eyal Shenitzky 2018-06-11 05:40:59 UTC
Hey Marcin,

I created a VM with a disk and write a script that does the following steps:

1. deactivate the disk using - 
attachmentService.update().diskAttachment(
                    diskAttachment()
                            .id(attachment.id())
                            .active(active))
                    .send().diskAttachment();

2. detach the disk from the VM using:
c.getDiskAttachmentSvc(attachment.id(), vmId)
                .remove().detachOnly(true).send();

3. attach the disk back to the VM
4. returns this steps 1000 times

I didn't fail on a 'conflict' but, I found this bug - bug 1588461 which you maybe encounter according to the logs you've attached.

So when this bug will fix I will close the bug and if you manage to reproduce it please reopen.

Is it sounds OK?

Comment 24 Eyal Shenitzky 2018-06-14 07:05:30 UTC
I also find bug 1589749

Comment 25 Eyal Shenitzky 2018-06-17 12:04:00 UTC
Marcin, did you attached the disk to the VM using 'virtio' interface?

Comment 26 Marcin 2018-06-25 12:46:45 UTC
Yes (Virtio-SCSI)

Comment 27 Tal Nisan 2018-07-05 12:38:23 UTC
This bug depends on Virt bug 1589749 which is not targeted yet, moving target release to 4.3 for now

Comment 28 Sandro Bonazzola 2019-01-28 09:42:03 UTC
This bug has not been marked as blocker for oVirt 4.3.0.
Since we are releasing it tomorrow, January 29th, this bug has been re-targeted to 4.3.1.

Comment 30 Eyal Shenitzky 2021-08-24 12:13:22 UTC
This bug/RFE is more than 2 years old and it didn't get enough attention so far, and is now flagged as pending close. 
Please review if it is still relevant and provide additional details/justification/patches if you believe it should get more attention for the next oVirt release.

Comment 31 Michal Skrivanek 2021-09-29 11:33:06 UTC
This bug didn't get any attention in a long time, and it's not planned in foreseeable future. oVirt development team has no plans to work on it.
Please feel free to reopen if you have a plan how to contribute this feature/bug fix.