Description of problem: Via SDK, Download disk image & try to pause it at 50% download, the download stop & rollback - I would expect it to continue the download. Also, the download although only 50% was done, by Event log it finishes successfully, see "Finalizing successful transfer" at engine log. I would expect to see an error about this invalid pause attempt. 2018-05-29 16:09:03,488+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-17) [a029e7cd-ef3f-449f-a1c8-c6670e3aeb6c] Invalid parameters: cannot move an image downlo ad to any kind of a paused state as the download is handled by the client and cannot be paused. Note that a download can be canceled if you wish to stop it. 2018-05-29 16:09:03,496+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-17) [a029e7cd-ef3f-449f-a1c8-c6670e3aeb6c] Transaction rolled-back for command 'org.ovirt. engine.core.bll.storage.disk.image.TransferImageStatusCommand'. 2018-05-29 16:09:03,498+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-17) [] Operation Failed: [] 2018-05-29 16:09:03,619+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-6) [3f55968e-3ed2-410e-a8b1-b68509b43184] Running command: TransferImageStatusCommand inte rnal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_DISK with role type USER 2018-05-29 16:09:03,622+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-6) [3f55968e-3ed2-410e-a8b1-b68509b43184] Updating image transfer be4cd43b-1a21-4276-8e16-65fdc8 d182fa (image 927cb30d-d38d-4660-8f71-7dd7361eb62c) phase to Finalizing Success 2018-05-29 16:09:05,741+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [06bfb499-133d-4ea5-9f94-a69a63594f9e] Finalizing succ essful transfer for Download disk 'disk_virtiocow_2916030102' (disk id: '927cb30d-d38d-4660-8f71-7dd7361eb62c', image id: '34bccad2-86ee-4468-b2ad-351287af95f3') 2018-05-29 16:09:05,744+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [06bfb499-133d-4ea5-9f94-a69a63594f9e] START, RemoveIm ageTicketVDSCommand(HostName = host_mixed_1, RemoveImageTicketVDSCommandParameters:{hostId='a354bdbb-953b-4ce3-9e0a-66672b5b33cb', ticketId='a12f6bc3-b600-492c-aa72-aa20776c38ff', timeout='null'}), log id: 3d870 0d7 2018-05-29 16:09:05,766+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [06bfb499-133d-4ea5-9f94-a69a63594f9e] FINISH, RemoveI mageTicketVDSCommand, return: StatusOnlyReturn [status=Status [code=0, message=Done]], log id: 3d8700d7 2018-05-29 16:09:05,766+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [06bfb499-133d-4ea5-9f94-a69a63594f9e] Successfully st opped image transfer session for ticket 'a12f6bc3-b600-492c-aa72-aa20776c38ff' 2018-05-29 16:09:05,766+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [06bfb499-133d-4ea5-9f94-a69a63594f9e] Removing image ticket from ovirt-imageio-proxy, id a12f6bc3-b600-492c-aa72-aa20776c38ff 2018-05-29 16:09:05,793+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [06bfb499-133d-4ea5-9f94-a69a63594f9e] Updating image tran sfer be4cd43b-1a21-4276-8e16-65fdc8d182fa (image 927cb30d-d38d-4660-8f71-7dd7361eb62c) phase to Finished Success Version-Release number of selected component (if applicable): 4.2.4-0.1.el7 How reproducible: 100% Steps to Reproduce: Via SDK only : 1.Start disk image download 2.When it reaches about ~50% download pause transfer Actual results: Download stop & rollback but in event log it states it finished download successfully. Expected results: 1) Download should not stop. 2) If download stops from an invalid action(pause) it should be stated in engine event log that it was finished successfully. Additional info:
Pausing a download should be handled only by client, covered in bug 1557770. I.e. invoking pause on image transfer is not supported for download. @Idan - can we add an error/warning event log when an sdk user tries to pause a download?
*** Bug 1583701 has been marked as a duplicate of this bug. ***
(In reply to Daniel Erez from comment #1) > Pausing a download should be handled only by client, covered in bug 1557770. > I.e. invoking pause on image transfer is not supported for download. > @Idan - can we add an error/warning event log when an sdk user tries to > pause a download? Error when SDK user tries invalid operation is most welcomed indeed. What about the more severe issue here which is that image download stops & rolls back when pause is received via SDK ?
(In reply to Avihai from comment #3) > (In reply to Daniel Erez from comment #1) > > Pausing a download should be handled only by client, covered in bug 1557770. > > I.e. invoking pause on image transfer is not supported for download. > > @Idan - can we add an error/warning event log when an sdk user tries to > > pause a download? > Error when SDK user tries invalid operation is most welcomed indeed. > > What about the more severe issue here which is that image download stops & > rolls back when pause is received via SDK ? Any chance to extract and attach a script that reproduces it? Couldn't reproduce it using a simple example script, where the pause simple fails without affecting the download.
(In reply to Daniel Erez from comment #4) > (In reply to Avihai from comment #3) > > (In reply to Daniel Erez from comment #1) > > > Pausing a download should be handled only by client, covered in bug 1557770. > > > I.e. invoking pause on image transfer is not supported for download. > > > @Idan - can we add an error/warning event log when an sdk user tries to > > > pause a download? > > Error when SDK user tries invalid operation is most welcomed indeed. > > > > What about the more severe issue here which is that image download stops & > > rolls back when pause is received via SDK ? > > Any chance to extract and attach a script that reproduces it? Couldn't > reproduce it using a simple example script, where the pause simple fails > without affecting the download. Yes , I reproduces it with a simpler script I use (see attached script called 'download_pause_resume_disk.py') When it reaches 50% download it sends SDK pause request & download ends . Ouput from consule: (.art) [~/git/rhevm-art]$ ~/sdk_scripts/download_pause_resume_disk.py *[TC18275] Completed: 0% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 0% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 1% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 2% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 3% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 3% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 4% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 5% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 6% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 7% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 7% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 8% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 9% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 10% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 10% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 11% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 12% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 13% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 14% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 14% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 15% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 16% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 17% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 17% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 18% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 19% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 20% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 21% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 21% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 22% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 23% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 24% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 25% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 25% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 26% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 27% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 28% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 28% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 29% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 30% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 31% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 32% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 32% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 33% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 34% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 35% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 35% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 36% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 37% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 38% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 39% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 39% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 40% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 41% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 42% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 42% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 43% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 44% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 45% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 46% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 46% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 47% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 48% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 49% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Completed: 50% on disk id 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Pause transfer on image 835c2bc8-8d41-4f18-83bc-bc7c17acbd99 Traceback (most recent call last): File "/home/aefrat/sdk_scripts/download_pause_resume_disk.py", line 154, in <module> transfer_service.pause() File "/home/aefrat/git/rhevm-art/.art/lib/python2.7/site-packages/ovirtsdk4/services.py", line 12374, in pause return self._internal_action(action, 'pause', None, headers, query, wait) File "/home/aefrat/git/rhevm-art/.art/lib/python2.7/site-packages/ovirtsdk4/service.py", line 299, in _internal_action return future.wait() if wait else future File "/home/aefrat/git/rhevm-art/.art/lib/python2.7/site-packages/ovirtsdk4/service.py", line 55, in wait return self._code(response) File "/home/aefrat/git/rhevm-art/.art/lib/python2.7/site-packages/ovirtsdk4/service.py", line 296, in callback self._check_fault(response) File "/home/aefrat/git/rhevm-art/.art/lib/python2.7/site-packages/ovirtsdk4/service.py", line 132, in _check_fault self._raise_error(response, body) File "/home/aefrat/git/rhevm-art/.art/lib/python2.7/site-packages/ovirtsdk4/service.py", line 118, in _raise_error raise error ovirtsdk4.Error: Fault reason is "Operation Failed". Fault detail is "[]". HTTP response code is 400. Engine: 018-05-30 13:58:21,335+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-22) [e5e154c3-c36a-4b23-a2ee-9452f9ec9a72] Invalid parameters: cannot move an image download to any kind of a paused state as the download is handled by the client and cannot be paused. Note that a download can be canceled if you wish to stop it. 2018-05-30 13:58:21,343+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-22) [e5e154c3-c36a-4b23-a2ee-9452f9ec9a72] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand'. 2018-05-30 13:58:21,344+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-22) [] Operation Failed: [] 2018-05-30 13:58:22,355+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-76) [755e99bb-5a9b-4290-8794-90c051fdb73f] START, GetImageTicketVDSCommand(HostName = host_mixed_2, GetImageTicketVDSCommandParameters:{hostId='2832e097-f1d7-446a-b2d9-6006625d12f2', ticketId='3dd173d7-2318-44e8-98be-245a31a1500e', timeout='null'}), log id: 472ff1ae 2018-05-30 13:58:22,393+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-76) [755e99bb-5a9b-4290-8794-90c051fdb73f] FINISH, GetImageTicketVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.ImageTicketInformation@6cc17e0f, log id: 472ff1ae 2018-05-30 13:58:22,405+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-76) [7b515518] Running command: TransferImageStatusCommand internal: true. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_DISK with role type USER 2018-05-30 13:58:22,413+03 WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-76) [7b515518] Trying to release a shared lock for key: '835c2bc8-8d41-4f18-83bc-bc7c17acbd99DISK' , but lock does not exist 2018-05-30 13:58:22,413+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-76) [7b515518] Lock freed to object 'EngineLock:{exclusiveLocks='', sharedLocks='[835c2bc8-8d41-4f18-83bc-bc7c17acbd99=DISK]'}' 2018-05-30 13:58:23,099+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-23) [1b3ec524-86f1-45c2-8ab3-c7835f4a0b90] Running command: TransferImageStatusCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_DISK with role type USER 2018-05-30 13:58:23,101+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-23) [1b3ec524-86f1-45c2-8ab3-c7835f4a0b90] Updating image transfer a61c3564-a541-4715-a3d8-1b39c8ef58c3 (image 835c2bc8-8d41-4f18-83bc-bc7c17acbd99) phase to Finalizing Success 2018-05-30 13:58:32,480+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] Finalizing successful transfer for Download disk 'test_download_disk' (disk id: '835c2bc8-8d41-4f18-83bc-bc7c17acbd99', image id: 'fb58c18d-f3b6-4e15-89a9-3de7321fd98b') 2018-05-30 13:58:32,482+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] START, RemoveImageTicketVDSCommand(HostName = host_mixed_2, RemoveImageTicketVDSCommandParameters:{hostId='2832e097-f1d7-446a-b2d9-6006625d12f2', ticketId='3dd173d7-2318-44e8-98be-245a31a1500e', timeout='null'}), log id: 4616344 2018-05-30 13:58:32,504+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] FINISH, RemoveImageTicketVDSCommand, return: StatusOnlyReturn [status=Status [code=0, message=Done]], log id: 4616344 2018-05-30 13:58:32,504+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] Successfully stopped image transfer session for ticket '3dd173d7-2318-44e8-98be-245a31a1500e' 2018-05-30 13:58:32,504+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] Removing image ticket from ovirt-imageio-proxy, id 3dd173d7-2318-44e8-98be-245a31a1500e 2018-05-30 13:58:32,538+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] Updating image transfer a61c3564-a541-4715-a3d8-1b39c8ef58c3 (image 835c2bc8-8d41-4f18-83bc-bc7c17acbd99) phase to Finished Success 2018-05-30 13:58:32,553+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] START, TeardownImageVDSCommand(HostName = host_mixed_2, ImageActionsVDSCommandParameters:{hostId='2832e097-f1d7-446a-b2d9-6006625d12f2'}), log id: 798d1105 2018-05-30 13:58:33,277+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-9) [755e99bb-5a9b-4290-8794-90c051fdb73f] FINISH, TeardownImageVDSCommand, return: StatusReturn:{status='Status [code=0, message=Done]'}, log id: 798d1105 2018-05-30 13:58:43,346+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-56) [755e99bb-5a9b-4290-8794-90c051fdb73f] Transfer was successful. Download disk 'test_download_disk' (disk id: '835c2bc8-8d41-4f18-83bc-bc7c17acbd99', image id: 'fb58c18d-f3b6-4e15-89a9-3de7321fd98b') 2018-05-30 13:58:44,356+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (EE-ManagedThreadFactory-engineScheduled-Thread-53) [755e99bb-5a9b-4290-8794-90c051fdb73f] Updating image transfer a61c3564-a541-4715-a3d8-1b39c8ef58c3 (image 835c2bc8-8d41-4f18-83bc-bc7c17acbd99) phase to Finished Success 2018-05-30 13:58:44,360+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-53) [755e99bb-5a9b-4290-8794-90c051fdb73f] Successfully transferred disk '00000000-0000-0000-0000-000000000000' (command id 'a61c3564-a541-4715-a3d8-1b39c8ef58c3') 2018-05-30 13:58:44,364+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-53) [755e99bb-5a9b-4290-8794-90c051fdb73f] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand' successfully. 2018-05-30 13:58:44,364+03 WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-53) [755e99bb-5a9b-4290-8794-90c051fdb73f] Trying to release a shared lock for key: '835c2bc8-8d41-4f18-83bc-bc7c17acbd99DISK' , but lock does not exist 2018-05-30 13:58:44,364+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-53) [755e99bb-5a9b-4290-8794-90c051fdb73f] Lock freed to object 'EngineLock:{exclusiveLocks='', sharedLocks='[835c2bc8-8d41-4f18-83bc-bc7c17acbd99=DISK]'}' 2018-05-30 13:58:44,379+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-53) [755e99bb-5a9b-4290-8794-90c051fdb73f] EVENT_ID: TRANSFER_IMAGE_SUCCEEDED(1,032), Image Download with disk test_download_disk succeeded.
Created attachment 1445774 [details] download with pause-resume script
Avihai, My solution for this bug only adds information for the error you get from the failure of transfer_service.pause() (Fault reason is "Operation Failed"), so now it should be more informative, and not show the error only in the engine's log. Note that your script calls to transfer_service.finalize() if you get an exception (like when not catching the one you get from transfer_service.pause()). The right thing to do here is catch exceptions you get from transfer_service and cancel the transfer using transfer_service.cancel(). Then, the transfer will move to CANCELLED rather than FINALIZING_SUCCESS.
(In reply to Idan Shaby from comment #7) > Avihai, > > My solution for this bug only adds information for the error you get from > the failure of transfer_service.pause() (Fault reason is "Operation > Failed"), so now it should be more informative, and not show the error only > in the engine's log. The main problem here is that calling transfer_service.pause() or any other illegal operation(like pause/resume) should not cause the transfer to fail or rollback - don't you agree? The proper handling, that any customer will also expect, would be to notify of the illegal operation but NOT stop/rollback the download or issue errors about stopping/rolling back -> cancel is not a solution here. How can I change the script so this negative test of sending illegal operations(pause/resume) will not fail the download/ upload? Can you please provide an example script? > Note that your script calls to transfer_service.finalize() if you get an > exception (like when not catching the one you get from > transfer_service.pause()). > The right thing to do here is caught exceptions you get from transfer_service > and cancel the transfer using transfer_service.cancel(). > Then, the transfer will move to CANCELLED rather than FINALIZING_SUCCESS. I will add an exception handling in the script BUT, as we should not stop the download when we send an illegal call like pause/resume so cancel is not the answer.
Idan , I changed the SDK script to except exception and cancel the transfer(see revised script) but still, I see in engine log that download is successful, no indication that cancel works. I think Nir/Daniel removed the cancel option for download as it's done only if inactivity timeout is reached, can you please check it out?
Created attachment 1448223 [details] revised_script_and_engine_log
Hi Avihai, As you said, your script lacked exception handling, and that was the problem. You had something like: try: a() pause() c() finally: finalize() When pause() was called, it raised an exception and you went straight to finalize() which moved the transfer to FINALIZING_SUCCESS state. I didn't say that you should cancel the whole download if you get an exception from pause(). I just said that you need a general try-except handling in any script that calls method that might raise in case that you don't take specific care of them. For example, if the pause method raises, you can print a log and continue to download. Nothing should stop you from doing that. I didn't take a deep look at your script so I don't know what its goal is, but you can definitely recover from such an exception and continue to download. What you did in your new script is also wrong - you didn't catch the exception that was raised from pause(), then you canceled the download in your except clause (your choice), and then for some reason you called to finalize() in your finally clause. Why would you want to cancel the download and then finalize it (which indeed moves the state to FINALIZING_SUCCESS)? I guess that what you wanted to do is: try: a() pause() # (maybe try and except here if you like) c() except: cancel() else: finalize() And indeed I removed the option to cancel a download from the webadmin. The reason for it was that it didn't really do anything, because the download is handled by the client and we can't control the client from the webadmin. But here it's different because your script is the client, and thus it can definitely cancel the download.
Hi Idan, Indeed after I changed the script to catch Exceptions right after transfer pause and resume the transfer continues & finished successfully. However, there is another issue that I saw that 'resume' transfer does not send an error message in the log and it appears to be allowed according to engine log: 6500202fcc0d] EVENT_ID: TRANSFER_IMAGE_RESUMED_BY_USER(1,074), Image transfer was resumed by user (admin@internal-authz) ->I'll open another bug on this resume unless you want to combine it with this bug. Now the script(Attached) flow looks like : try: while pos < start_transfer() try: pause() except: print relevant message try: resume() except: print relevant message except: print relevant message else: finalize() More detailed Engine log: - Pause section: 2018-06-17 11:42:16,013+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-11) [e36908ed-12b4-495c-a660-4d01d32a122d] Invalid parameters: cannot move an image download to any kind of a paused state as the download is handled by the client and cannot be paused. Note that a download can be canceled if you wish to stop it. 2018-06-17 11:42:16,029+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-11) [e36908ed-12b4-495c-a660-4d01d32a122d] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand'. 2018-06-17 11:42:16,032+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-11) [] Operation Failed: [] 2018-06-17 11:42:16,171+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-30) [559b92c0-6b94-48df-8b94-98512a4475ee] Running command: TransferImageStatusCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_DISK with role type USER - Resume section 2018-06-17 11:42:16,175+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-30) [559b92c0-6b94-48df-8b94-98512a4475ee] Updating image transfer fe260258-74d5-434e-8068-9607b1653e5a (image 1ebcf398-3023-4c9e-ab50-c24b09c19dcb) phase to Resuming 2018-06-17 11:42:16,228+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-29) [f297b541-1822-4077-a65b-eab640947970] Running command: TransferImageStatusCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_DISK with role type USER 2018-06-17 11:42:16,873+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-88) [bf2ac043-d1b3-4b73-9004-6500202fcc0d] Resuming transfer for Download disk 'download_disk1' (disk id: '1ebcf398-3023-4c9e-ab50-c24b09c19dcb', image id: 'bc4c4c6c-f73a-453c-9298-f0657b8a672f') 2018-06-17 11:42:16,901+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-88) [bf2ac043-d1b3-4b73-9004-6500202fcc0d] EVENT_ID: TRANSFER_IMAGE_RESUMED_BY_USER(1,074), Image transfer was resumed by user (admin@internal-authz).
Created attachment 1452342 [details] engine log and revised script
Yes, this shouldn't happen and needs to be fixed. Please open another bug for that. Note that your script doesn't make much sense because it tries to resume the download even if it couldn't pause it. But that's just a comment about the script, the engine should fail the attempt to resume an ongoing download. Thanks!
Bug 1592114, which was mentioned by Avihai in comment 12, was targeted to oVirt 4.2.5, but it requires the patch that solves this bug (which was only merged to master). Can we target this bug to 4.2.5, too? The fix is not complicated at all.
Sure, makes sense. Please backport this one first.
Tested using Avihai's script and ovirt-engine-4.2.5-0.1.el7ev.noarch Actual result: After the image was ~50% downloaded, the script tried to pause the download and failed, it tried to resume it but failed again (as expected)and then it continued. log: ... Completed: 48% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 Completed: 49% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 Completed: 50% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 Pause transfer on image 88dbe09b-b576-4939-9972-d49c5cc05d87 Pause failed as expected with exception Fault reason is "Operation Failed". Fault detail is "[Cannot pause image download as it's handled by the client. Note that it can be canceled if you wish to stop it.]". HTTP response code is 400. Resume transfer on image 88dbe09b-b576-4939-9972-d49c5cc05d87 Resume failed as expected with exception Fault reason is "Operation Failed". Fault detail is "[Cannot resume image transfer as it's not in a paused state.]". HTTP response code is 409. Completed: 50% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 Completed: 51% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 Completed: 52% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 Completed: 53% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 Completed: 53% on disk id 88dbe09b-b576-4939-9972-d49c5cc05d87 ... Moving to VERIFIED
This bugzilla is included in oVirt 4.2.5 release, published on July 30th 2018. Since the problem described in this bug report should be resolved in oVirt 4.2.5 release, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report.