Bug 1856826

Created attachment 1701045 [details]
transfer with pause logs

Description of problem:

This issue is discovered by automation, making this an automation blocker, but reproduced manually as well.
When pausing and uploading disk permutations (qcow2_v2 / qcow2_v3 / raw) and trying to resume the upload, the disk remains in "paused by system state" which is seen by the UI, or 'locked' state as seen from the logs.

Here we are pausing the upload transfer:

2020-07-12 19:59:18,675+03 INFO  [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-45) [1168f209-8de8-4402-8411-1e4efe959e5a] Transfer was paused by user. Upload disk 'disk_qcow2_v2
_1219574589' (disk id: '8a443238-2fc4-45c5-9dda-cc11d658039d', image id: '25df50aa-cf26-44e7-8c72-06aafe02157b')

Here we attempt to resume it:

2020-07-12 20:00:11,820+03 INFO  [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-15) [f0066986-92f9-44d0-9154-665148bfa6b3] Updating image transfer d7233f8f-7f0c-411a-a92c-208e82a4d507 (image 8a443238-2fc4-45c5-9dda-cc11d658039d) phase to Resuming


The ticket is being renewed:

2020-07-12 20:00:19,074+03 INFO  [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-88) [1168f209-8de8-4402-8411-1e4efe959e5a] Renewing transfer ticket for Upload disk 'disk_qcow2_v2_1219574589' (disk id: '8a443238-2fc4-45c5-9dda-cc11d658039d', image id: '25df50aa-cf26-44e7-8c72-06aafe02157b')


But the transfer is failing to resume due to locked disk:

2020-07-12 20:00:26,234+03 WARN  [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (default task-21) [ba7499d1-40b2-4af4-adb2-1119b2ed2b74] Validation of action 'TransferDiskImage' failed for user admin@internal-authz. Reasons: VAR__TYPE__DISK,VAR__ACTION__TRANSFER,ACTION_TYPE_FAILED_DISKS_LOCKED,$diskAliases disk_qcow2_v2_1219574589
2020-07-12 20:00:26,234+03 INFO  [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (default task-21) [ba7499d1-40b2-4af4-adb2-1119b2ed2b74] Lock freed to object 'EngineLock:{exclusiveLocks='[8a443238-2fc4-45c5-9dda-cc11d658039d=DISK]', sharedLocks='[]'}'
2020-07-12 20:00:26,235+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-21) [] Operation Failed: [Cannot transfer Virtual Disk: The following disks are locked: disk_qcow2_v2_1219574589. Please try again in a few minutes.]


On hosts daemon log we only see Timeout reading or writing to socket:

2020-07-12 20:00:11,750 INFO    (Thread-39) [backends.file] Close backend path='/rhev/data-center/mnt/blockSD/e7c18de5-dbc4-466e-934b-02b395b75692/images/8a443238-2fc4-45c5-9dda-cc11d658039d/25df50aa-cf26-44e7-8c72-06aafe02157b' dirty=True
2020-07-12 20:00:11,935 WARNING (Thread-41) [http] Timeout reading or writing to socket: The read operation timed out


On Engine daemon there is "socket.timeout: The read operation timed out" exception:

http://pastebin.test.redhat.com/883594


Version-Release number of selected component (if applicable):
rhv-release-4.4.1-11-001.noarch

How reproducible:
Reproduced by two tier2 automation runs.
Also reproduced manually from the UI

Steps to Reproduce:
    1. Uploads of disk images (raw, qcow2_v3, qcow2_v3, ISO) from localhost
    2. Only If pause is enabled than Reaching 50% upload initiate pause wait
        for a defined timeout & resume uploads
    3. Verify data correctness via md5sum of original and uploaded images

Actual results:
Upload is not resumed after pause.

Expected results:
After resuming, the upload should proceed.

Attaching also logs for a manual reproduction (from the UI)