Bug 1977276

Summary:	Uploading ISO through RHV-M portal intermittently fails with error "Failed to add disk for image transfer command"
Product:	Red Hat Enterprise Virtualization Manager	Reporter:	nijin ashok <nashok>
Component:	ovirt-engine	Assignee:	Nir Soffer <nsoffer>
Status:	CLOSED ERRATA	QA Contact:	sshmulev
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	4.4.6	CC:	ahadas, bcholler, dfodor, emarcus, eshenitz, ffutigam, nsoffer, wdh
Target Milestone:	ovirt-4.4.9	Keywords:	ZStream
Target Release:	---	Flags:	sshmulev: testing_plan_complete+
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:	Previously, in some cases, adding a new disk for the upload succeeded, but the system handled the operation as a failure. AS a result, the upload failed silently without uploading any data and ending in an empty new disk. In this release, the add disk success is detected correctly, and uploading completes successfully.	Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-11-16 14:46:53 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:

Description nijin ashok 2021-06-29 11:24:25 UTC

Description of problem:

Uploading ISO through the RHV-M portal is intermittently failing with the below error in the engine log.

===
2021-06-29 16:27:59,373+05 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-48) [efbee3a9-c19d-4bd9-957d-959e8cbb48dd] Failed to add disk for image transfer command '599af07b-3421-481a-b300-99affe1e5002'
===

However, the disk was added successfully.

===
2021-06-29 16:27:58,365+05 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-58) [] EVENT_ID: USER_ADD_DISK_FINISHED_SUCCESS(2,021), The disk 'CentOS-7-x86_64-Minimal-2009.iso' was successfully added.
====

I was able to add the same ISO on the third attempt.

===
2021-06-29 16:30:48,799+05 INFO  [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [a9caa7a8-e6e5-4f2d-88a8-8fff39b3f569] Successfully added Upload disk 'CentOS-7-x86_64-Minimal-2009-2.iso' (disk id: '97b31fab-4a72-44e9-bb35-a5a3ac7d533c', image id: '1dc5061f-622e-4523-9b62-7f9fa35cd942') for image transfer command '9a5f0631-89ec-4b61-9c9a-403e39c057ed'

2021-06-29 16:30:51,039+05 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-25) [] EVENT_ID: USER_ADD_DISK_FINISHED_SUCCESS(2,021), The disk 'CentOS-7-x86_64-Minimal-2009-2.iso' was successfully added.

2021-06-29 16:37:28,000+05 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [a9caa7a8-e6e5-4f2d-88a8-8fff39b3f569] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk CentOS-7-x86_64-Minimal-2009-2.iso succeeded.
===

It looks like some sync issue in adding the disk and "image transfer command".

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

rhvm-4.4.6.8-0.1.el8ev.noarch

How reproducible:

3 out of 4 attempts failed in my test environment.

Steps to Reproduce:

1. Upload an ISO to the data storage domain. 

Actual results:

Uploading ISO through RHV-M portal intermittently fails with error "Failed to add disk for image transfer command"

Expected results:

Uploading should work.

Additional info:

Comment 4 Nir Soffer 2021-09-09 09:33:04 UTC

Also reported on users mailing lists several times. Last report was here:
https://lists.ovirt.org/archives/list/users@ovirt.org/thread/CJISJIDQKSINIJUA5UO6Y4BRFQYEOYLA/

Comment 5 W. de Heiden 2021-09-22 11:55:41 UTC

Confirmed for oVirt 4.4.8.5-1.el8 on CentOS Stream 8.

Comment 8 sshmulev 2021-10-10 08:18:48 UTC

Verified.

Version:
ovirt-engine-4.4.9.1-0.13.el8ev.noarch

Steps:
Upload ISO to same storage domains and also different ones successfully.

10 times passed without error log:

2021-10-10 11:05:21,538+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-80) [44eb4fc6-01d6-4ec0-bc00-1aa873148d28] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:05:57,002+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-95) [e75d21b8-efee-40e5-ab15-64ea81f253d6] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:06:08,722+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-85) [430a0590-c938-4cdb-9c14-6ad69d053197] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:06:56,357+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-93) [0a2f9d2e-18c1-41ab-bf8d-52d58847bcb5] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:07:24,157+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-54) [47fe8cf8-54e4-4098-83d7-3c0914a03a68] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:08:04,109+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-26) [8d761818-0d4b-488d-83b5-ea84d4af276c] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:08:46,860+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-63) [26c21258-a423-4019-88b2-67643283d651] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:08:46,965+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-63) [903faf9d-93e5-48fa-9a7e-709300239408] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:08:56,652+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-60) [89d119a5-f068-48e9-b145-09502aacf26d] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.
2021-10-10 11:09:06,942+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [d1d2c6e6-a636-4d37-bb91-80457e96fdc1] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Upload with disk hdat2cd_lite_74.iso succeeded.




Tried the same steps on an older version and it failed on the first try (ovirt-engine-4.4.9-0.6.el8ev.noarch)

2021-10-10 10:51:40,217+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [660be426-0276-42b7-bc83-df60abe14a21] Failed to add disk for image transfer command '75be1e9d-43ab-4914-acf2-94c0b18f4308'
2021-10-10 10:51:41,259+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-13) [61eca765] Failed to transfer disk '00000000-0000-0000-0000-000000000000' (command id '75be1e9d-43ab-4914-acf2-94c0b18f4308')
2021-10-10 10:51:41,340+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-13) [660be426-0276-42b7-bc83-df60abe14a21] Error during log command: org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand: 'NullPointerException: '

2021-10-10 11:07:21,184+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-53) [2eea4228-ad4f-4206-92cc-1e481367640a] Failed to add disk for image transfer command '13100453-8e42-4142-a168-f2730736126e'
2021-10-10 11:07:22,258+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [251286ff] Failed to transfer disk '00000000-0000-0000-0000-000000000000' (command id '13100453-8e42-4142-a168-f2730736126e')
2021-10-10 11:07:22,263+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [2eea4228-ad4f-4206-92cc-1e481367640a] Error during log command: org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand: 'NullPointerException: '

Comment 12 errata-xmlrpc 2021-11-16 14:46:53 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: RHV Manager (ovirt-engine) security update [ovirt-4.4.9]), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2021:4626