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

Bug 2131470

Summary: Image transfer status is changed to "Finalizing Success" if we finalize a "Finished Success" transfer
Product: Red Hat Enterprise Virtualization Manager Reporter: nijin ashok <nashok>
Component: ovirt-engineAssignee: Nobody <nobody>
Status: CLOSED DUPLICATE QA Contact: Shir Fishbain <sfishbai>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 4.5.1CC: ahadas, aperotti, bcholler, gveitmic, mavital, michal.skrivanek, mperina
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-10-06 07:06:24 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:    
Bug Blocks: 1541529    

Description nijin ashok 2022-10-01 15:29:28 UTC
Description of problem:

Used download_disk_snapshot.py to download a snapshot image. The transfer was completed successfully and the transfer status was changed to 'Finished Success'.

~~~
2022-10-01 18:56:39,065+05 INFO  [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-2) [f2327d87-84a7-4f4b-b6fa-8015957ef713] Updating image transfer 'd5c3c9d3-ead1-4395-9186-a3994e1b5ad7' phase from 'Finalizing Success' to 'Finished Success'
2022-10-01 18:56:39,103+05 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-2) [f2327d87-84a7-4f4b-b6fa-8015957ef713] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Download with disk myvn_Disk1 succeeded.
~~~

Send another "finalize" request to the same image transfer command.

~~~
# curl --insecure --request POST --header 'Version: 4' --header 'Accept: application/xml' --header 'Content-Type: application/xml'  --data '<action/>'  --user 'admin@internal:mypass'  https://manager.shiftvirt.com/ovirt-engine/api/imagetransfers/d5c3c9d3-ead1-4395-9186-a3994e1b5ad7/finalize
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<action>
    <status>complete</status>
</action>
~~~

The status is now back to `Finalizing Success` from `Finished Success`.

~~~
2022-10-01 19:14:53,469+05 INFO  [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-42) [d67caeb4-3686-4227-b605-b33e3a7af2f9] Updating image transfer 'd5c3c9d3-ead1-4395-9186-a3994e1b5ad7' phase from 'Finished Success' to 'Finalizing Success'
~~~

And this entry stays in the database and this can cause issues in snapshot flow as explained below.

Tried the same flow again which creates two imagetransfer entries for the disk.

~~~
engine=# select command_id,disk_id,phase from image_transfers where disk_id='6391823b-34fd-4ce8-9f7d-8a62319fcc94';
              command_id              |               disk_id                | phase
--------------------------------------+--------------------------------------+-------
 1c0e54bb-9519-4ea5-b297-5b12d03a267c | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 |     7
 d5c3c9d3-ead1-4395-9186-a3994e1b5ad7 | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 |     7
(2 rows)
~~~

Now the `images_storage_domain_view` give duplicate entries which are referred during snapshot create and delete operations.

~~~
engine=# select image_guid,image_group_id,vm_snapshot_id from images_storage_domain_view where disk_id = '6391823b-34fd-4ce8-9f7d-8a62319fcc94';
              image_guid              |            image_group_id            |            vm_snapshot_id
--------------------------------------+--------------------------------------+--------------------------------------
 a7a3c038-b788-4355-b35b-097b156312ec | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 | a1600a79-8e65-4445-af54-5ff2781966f1
 a7a3c038-b788-4355-b35b-097b156312ec | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 | a1600a79-8e65-4445-af54-5ff2781966f1
 4c88e42e-8f13-4c87-a40a-c72802e9ead9 | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 | 5173281a-a966-47b0-9cb1-9dfac362b32e
 4c88e42e-8f13-4c87-a40a-c72802e9ead9 | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 | 5173281a-a966-47b0-9cb1-9dfac362b32e
(4 rows)
~~~

Deleting this snapshot will fail with the error below:

~~~
2022-10-01 19:48:44,786+05 INFO  [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotCommand] (default task-47) [ca55a7e2-b675-4b74-a4e4-3e94ff4f1491] Lock freed to object 'EngineLock:{exclusiveLocks='[e110655d-06bb-41ec-b5cd-da7c75658550=VM]', sharedLocks=''}'
2022-10-01 19:48:45,075+05 ERROR [org.ovirt.engine.core.bll.GetVmConfigurationBySnapshotQuery] (default task-47) [d973b2ef-ebc1-4cd5-ada0-9794916bb7b6] Query 'GetVmConfigurationBySnapshotQuery' failed: Duplicate key 4c88e42e-8f13-4c87-a40a-c72802e9ead9 (attempted merging values org.ovirt.engine.core.common.businessentities.storage.DiskImage@ff49c3c5 and org.ovirt.engine.core.common.businessentities.storage.DiskImage@ff49c3c5)
2022-10-01 19:48:45,075+05 ERROR [org.ovirt.engine.core.bll.GetVmConfigurationBySnapshotQuery] (default task-47) [d973b2ef-ebc1-4cd5-ada0-9794916bb7b6] Exception: java.lang.IllegalStateException: Duplicate key 4c88e42e-8f13-4c87-a40a-c72802e9ead9 (attempted merging values org.ovirt.engine.core.common.businessentities.storage.DiskImage@ff49c3c5 and org.ovirt.engine.core.common.businessentities.storage.DiskImage@ff49c3c5)
	at java.base/java.util.stream.Collectors.duplicateKeyException(Collectors.java:133)
	at java.base/java.util.stream.Collectors.lambda$uniqKeysMapAccumulator$1(Collectors.java:180)
	at java.base/java.util.stream.ReduceOps$3ReducingSink.accept(ReduceOps.java:169)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
.....
......
	at io.undertow.servlet.13.SP2-redhat-00001//io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:79)
	at io.undertow.servlet.13.SP2-redhat-00001//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:100)
	at io.undertow.core.13.SP2-redhat-00001//io.undertow.server.Connectors.executeRootHandler(Connectors.java:387)
	at io.undertow.core.13.SP2-redhat-00001//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:852)
	at org.jboss.threads.0.Final-redhat-00001//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads.0.Final-redhat-00001//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
	at org.jboss.threads.0.Final-redhat-00001//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads.0.Final-redhat-00001//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at org.jboss.xnio.5.SP1-redhat-00001//org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1280)
	at java.base/java.lang.Thread.run(Thread.java:829)
~~~

Also it can cause duplicate entries in the images table if this two imagetransfer exists while creating a new snapshot.

Here, I deleted both the imagetransfer from the database, deleted the snapshot, and did the same flow to create two imagetrasfer entries with phase=7.

Now the view `all_disks_for_vms` which lists active images of the disks will have duplicate entries.

~~~
engine=# SELECT image_guid,disk_id from all_disks_for_vms where disk_id = '6391823b-34fd-4ce8-9f7d-8a62319fcc94';
              image_guid              |               disk_id
--------------------------------------+--------------------------------------
 4c88e42e-8f13-4c87-a40a-c72802e9ead9 | 6391823b-34fd-4ce8-9f7d-8a62319fcc94
 4c88e42e-8f13-4c87-a40a-c72802e9ead9 | 6391823b-34fd-4ce8-9f7d-8a62319fcc94
(2 rows)
~~~

This view is used by the function getdisksvmguid to get the list of active disks while creating the snapshot. So it gets two entries and attempts to create a snapshot on the same disk twice:

~~~
2022-10-01 20:43:39,398+05 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (EE-ManagedThreadFactory-engine-Thread-80383) [65023df7-3d8d-4a72-bc20-ec4525858d74] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='71cf243c-edec-11eb-aa8c-002b6a01557c', ignoreFailoverLimit='false', storageDomainId='1bfb1005-b98d-4592-9c1d-5c04292584ed', imageGroupId='6391823b-34fd-4ce8-9f7d-8a62319fcc94', imageSizeInBytes='1073741824', volumeFormat='COW', newImageId='8ccd22de-11aa-4719-9010-9fa55f4af1ba', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='4c88e42e-8f13-4c87-a40a-c72802e9ead9', sourceImageGroupId='6391823b-34fd-4ce8-9f7d-8a62319fcc94', shouldAddBitmaps='true', legal='true', sequenceNumber='2', bitmap='null'}), log id: 75e95872

2022-10-01 20:43:39,822+05 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (EE-ManagedThreadFactory-engine-Thread-80383) [65023df7-3d8d-4a72-bc20-ec4525858d74] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='71cf243c-edec-11eb-aa8c-002b6a01557c', ignoreFailoverLimit='false', storageDomainId='1bfb1005-b98d-4592-9c1d-5c04292584ed', imageGroupId='6391823b-34fd-4ce8-9f7d-8a62319fcc94', imageSizeInBytes='1073741824', volumeFormat='COW', newImageId='37bc17ca-ceec-4629-afc4-e2568bc0b6bf', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='4c88e42e-8f13-4c87-a40a-c72802e9ead9', sourceImageGroupId='6391823b-34fd-4ce8-9f7d-8a62319fcc94', shouldAddBitmaps='true', legal='true', sequenceNumber='3', bitmap='null'}), log id: 5dd824a5
~~~

Resulting in duplicate entries in the images table:

~~~
engine=# select image_guid,image_group_id,parentid,vm_snapshot_id from images where image_group_id = '6391823b-34fd-4ce8-9f7d-8a62319fcc94';
              image_guid              |            image_group_id            |               parentid               |            vm_snapshot_id
--------------------------------------+--------------------------------------+--------------------------------------+--------------------------------------
 8ccd22de-11aa-4719-9010-9fa55f4af1ba | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 | 4c88e42e-8f13-4c87-a40a-c72802e9ead9 | 5e406256-45f2-489d-9a1f-b97136fc2e96 <<<
 37bc17ca-ceec-4629-afc4-e2568bc0b6bf | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 | 4c88e42e-8f13-4c87-a40a-c72802e9ead9 | 5e406256-45f2-489d-9a1f-b97136fc2e96 <<<
 4c88e42e-8f13-4c87-a40a-c72802e9ead9 | 6391823b-34fd-4ce8-9f7d-8a62319fcc94 | 00000000-0000-0000-0000-000000000000 | a1600a79-8e65-4445-af54-5ff2781966f1
(3 rows)
~~~ 
 

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

rhvm-4.5.1.3-0.28.el8ev.noarch

How reproducible:

100%

Steps to Reproduce:

1. Download a snapshot image using https://github.com/oVirt/python-ovirt-engine-sdk4/blob/main/examples/download_disk_snapshot.py
2. Once the disk is downloaded, send a finalize request to the same imagetransfer. The imagetransfer status moves to "Finalizing Success".
3. Do the same flow again which will create two "Finalizing Success" imagetransfer.
4. Try deleting the snapshot.

Actual results:

Image transfer status is changed to "Finalizing Success" if we finalize a "Finished Success" transfer 

Expected results:

The "Finished Success" is the last stage of an imagetransfer and the engine should prevent modifying the imagetransfer status at this stage. 

Additional info:

Comment 3 Michal Skrivanek 2022-10-05 12:20:20 UTC
a duplicate of bug 2123141 / bug 2092816 validating the final status transition

upcoming RHV build contains the fix already, please confirm it fixes this issue

Comment 4 nijin ashok 2022-10-06 03:59:19 UTC
(In reply to Michal Skrivanek from comment #3)
> a duplicate of bug 2123141 / bug 2092816 validating the final status
> transition
> 
> upcoming RHV build contains the fix already, please confirm it fixes this
> issue

Yes, it fixes the issue and blocks the transition.

2022-10-06 09:25:32,654+05 ERROR [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-7) [e562db0c-9f5f-41a6-919f-49b43878d3e8] Image transfer 'a6ff071f-86cb-4965-9979-303374710009' transition from phase 'Finished Success' to 'Finalizing Success' is invalid