1514887 – ImageIO- Reboot proxy VDSM host during disk upload - upload can't be cancled/resumed - RemoveImageTicketVDS failed - The resource could not be found

Bug 1514887 - ImageIO- Reboot proxy VDSM host during disk upload - upload can't be cancled/resumed - RemoveImageTicketVDS failed - The resource could not be found

Summary: ImageIO- Reboot proxy VDSM host during disk upload - upload can't be cancled/...

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	ovirt-engine
Classification:	oVirt
Component:	BLL.Storage
Sub Component:
Version:	4.2.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	high
Target Milestone:	ovirt-4.2.0
Target Release:	---
Assignee:	Idan Shaby
QA Contact:	Avihai
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-11-19 09:01 UTC by Avihai
Modified:	2017-12-20 11:19 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2017-12-20 11:19:16 UTC
oVirt Team:	Storage
Embargoed:
Dependent Products:
Flags:	rule-engine: ovirt-4.2+

Attachments	(Terms of Use)
engine , vdsm ,image_proxy,image_demon logs (2.85 MB, application/x-gzip) 2017-11-19 09:01 UTC, Avihai	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
oVirt gerrit	84341	0	master	ABANDONED	core: TransferImage - pause on remove ticket failure	2017-11-23 12:44:56 UTC
oVirt gerrit	84385	0	master	MERGED	backend: maintain a single ticket per transfer	2017-11-23 12:28:06 UTC

Description Avihai 2017-11-19 09:01:21 UTC

Created attachment 1355061 [details]
engine , vdsm ,image_proxy,image_demon logs

Description of problem:
Reboot proxy VDSM host during upload - upload can't be canceled/resumed


Version-Release number of selected component (if applicable):
ovirt-engine-4.2.0-0.0.master.20171114111003.git7aa1b91.el7.centos.noarch
4.20.7-1.gitc9cf1ee

How reproducible:
After the host reboot it happens each time I try to cancel/resume upload image.

Steps to Reproduce:
1. Start disk upload via UI & check which host is the imaged-host-uri
   (in this case  storage-ge8-vdsm1.scl.lab.tlv.redhat.com) 
2. Reboot that host.(storage-ge8-vdsm1.scl.lab.tlv.redhat.com)
3. After host is up, the disk is at "Paused by System" state which is expected (see Bug 1508844 for more details)
4. Try to cancel/resume the upload.
 
Actual results:
As early as step 3 (after host reboot ) the engine gets filled with errors each 10sec that does not stop.

the engine is filled with Errors saying RemoveImageTicketVDS failed with the explanation that The resource could not be found.

"
command RemoveImageTicketVDS failed: Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., 
"

Same errors appear at Cancel/Resume of that upload and Cancel/Resume does not start.(image IO & proxy logs does not show anything special while trying to cancel/resume)

Engine after cancle:
2017-11-19 10:20:30,108+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] START, GetImageTicketVDSCommand(HostName = host_mixed_1, GetImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'}), log id: 26682a64
2017-11-19 10:20:30,128+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Failed in 'GetImageTicketVDS' method
2017-11-19 10:20:30,169+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command GetImageTicketVDS failed: Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"
2017-11-19 10:20:30,169+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand' return value 'ImageTicketInformationReturn:{status='Status [code=482, message=Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"]'}'
2017-11-19 10:20:30,169+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] HostName = host_mixed_1
2017-11-19 10:20:30,170+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Command 'GetImageTicketVDSCommand(HostName = host_mixed_1, GetImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'})' execution failed: VDSGenericException: VDSErrorException: Failed to GetImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482
2017-11-19 10:20:30,170+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] FINISH, GetImageTicketVDSCommand, log id: 26682a64
2017-11-19 10:20:30,170+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to GetImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482 (Failed with error ImageDeamonError and code 482)
2017-11-19 10:20:30,186+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand'.

After resume:
Cancle:
Engine:
2017-11-19 10:20:30,108+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] START, GetImageTicketVDSCommand(HostName = host_mixed_1, GetImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'}), log id: 26682a64
2017-11-19 10:20:30,128+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Failed in 'GetImageTicketVDS' method
2017-11-19 10:20:30,169+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command GetImageTicketVDS failed: Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"
2017-11-19 10:20:30,169+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand' return value 'ImageTicketInformationReturn:{status='Status [code=482, message=Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"]'}'
2017-11-19 10:20:30,169+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] HostName = host_mixed_1
2017-11-19 10:20:30,170+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Command 'GetImageTicketVDSCommand(HostName = host_mixed_1, GetImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'})' execution failed: VDSGenericException: VDSErrorException: Failed to GetImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482
2017-11-19 10:20:30,170+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] FINISH, GetImageTicketVDSCommand, log id: 26682a64
2017-11-19 10:20:30,170+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to GetImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482 (Failed with error ImageDeamonError and code 482)
2017-11-19 10:20:30,186+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (EE-ManagedThreadFactory-engine-Thread-88178) [52756f8b-4059-4da8-84d6-ff9ad7cedd0c] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand'.



RESUME:
2017-11-19 10:48:36,089+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] Running command: TransferImageStatusCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_DISK with role type USER
2017-11-19 10:48:36,098+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] START, GetImageTicketVDSCommand(HostName = host_mixed_1, GetImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'}), log id: 4c1cf0b9
2017-11-19 10:48:36,117+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] Failed in 'GetImageTicketVDS' method
2017-11-19 10:48:36,126+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command GetImageTicketVDS failed: Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"
2017-11-19 10:48:36,126+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand' return value 'ImageTicketInformationReturn:{status='Status [code=482, message=Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"]'}'
2017-11-19 10:48:36,126+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] HostName = host_mixed_1
2017-11-19 10:48:36,126+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] Command 'GetImageTicketVDSCommand(HostName = host_mixed_1, GetImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'})' execution failed: VDSGenericException: VDSErrorException: Failed to GetImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482
2017-11-19 10:48:36,126+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetImageTicketVDSCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] FINISH, GetImageTicketVDSCommand, log id: 4c1cf0b9
2017-11-19 10:48:36,126+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] Command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to GetImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482 (Failed with error ImageDeamonError and code 482)
2017-11-19 10:48:36,143+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-8) [aa46e1db-f6b6-4885-8db1-bffde71b6c52] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand'.


Expected results:


Additional info:
After the reboot of the host each 10 seconds I get the following error:
VDSM host_mixed_1 command RemoveImageTicketVDS failed: Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"

Engine log:
2017-11-15 16:38:38,124+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] START, RemoveImageTicketVDSCommand(HostName = host_mixed_1, RemoveImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'}), log id: 7ca5ad04
2017-11-15 16:38:38,151+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] Failed in 'RemoveImageTicketVDS' method
2017-11-15 16:38:38,160+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command RemoveImageTicketVDS failed: Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"
2017-11-15 16:38:38,160+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand' return value 'StatusOnlyReturn [status=Status [code=482, message=Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found"]]'
2017-11-15 16:38:38,160+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] HostName = host_mixed_1
2017-11-15 16:38:38,161+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] Command 'RemoveImageTicketVDSCommand(HostName = host_mixed_1, RemoveImageTicketVDSCommandParameters:{hostId='344b358c-8d50-4635-be66-19b20ef31ed5', ticketId='2910890b-77a8-419d-9a65-da8ebbc0f554', timeout='null'})' execution failed: VDSGenericException: VDSErrorException: Failed to RemoveImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482
2017-11-15 16:38:38,161+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] FINISH, RemoveImageTicketVDSCommand, log id: 7ca5ad04
2017-11-15 16:38:38,161+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-59) [13893784-f38d-4e15-a016-0160804106e9] Failed to stop image transfer session for ticket '2910890b-77a8-419d-9a65-da8ebbc0f554': {}: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to RemoveImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482 (Failed with error ImageDeamonError and code 482)
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.stopImageTransferSession(TransferImageCommand.java:639) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.handlePaused(TransferImageCommand.java:441) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.handlePausedSystem(TransferImageCommand.java:344) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.executeStateHandler(TransferImageCommand.java:162) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.proceedCommandExecution(TransferImageCommand.java:140) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommandCallback.doPolling(TransferImageCommandCallback.java:21) [bll.jar:]
        at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:145) [bll.jar:]
        at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106) [bll.jar:]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_151]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [rt.jar:1.8.0_151]
        at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) [javax.enterprise.concurrent-1.0.jar:]
        at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) [javax.enterprise.concurrent-1.0.jar:]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_151]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_151]
        at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_151]
        at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) [javax.enterprise.concurrent-1.0.jar:]
        at org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)
Caused by: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to RemoveImageTicketVDS, error = Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found", code = 482

VDSM:
2017-11-15 16:38:48,204+0200 ERROR (jsonrpc/5) [storage.Dispatcher] FINISH remove_image_ticket error=Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be fo
und., detail=No such ticket u'2910890b-77a8-419d-9a65-da8ebbc0f554', reason=Not Found" (dispatcher:82)


daemon log :
2017-11-15 16:38:38,136 INFO    (ticket.server) [tickets] Removing ticket 2910890b-77a8-419d-9a65-da8ebbc0f554
2017-11-15 16:38:38,137 WARNING (ticket.server) [web] / - DELETE /2910890b-77a8-419d-9a65-da8ebbc0f554 404 154 (0.00s)
2017-11-15 16:38:48,194 INFO    (ticket.server) [tickets] Removing ticket 2910890b-77a8-419d-9a65-da8ebbc0f554
2017-11-15 16:38:48,195 WARNING (ticket.server) [web] / - DELETE /2910890b-77a8-419d-9a65-da8ebbc0f554 404 154 (0.00s)

Image proxy log:
(Thread-153) ERROR 2017-11-15 16:27:55,701 images:185:root:(make_imaged_request) Failed communicating with host: A Connection error occurred.
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/images.py", line 176, in make_imaged_request
    timeout=timeout, stream=stream)
  File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 576, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python2.7/site-packages/requests/adapters.py", line 415, in send
    raise ConnectionError(err, request=request)
ConnectionError: ('Connection aborted.', error(111, 'Connection refused'))
(Thread-153) ERROR 2017-11-15 16:27:55,702 web:89:web:(log_response) 10.35.4.39 - PUT  503 208 (0.06s)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/web.py", line 48, in __call__
    resp = self.dispatch(request)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/web.py", line 73, in dispatch
    return method(*match.groups())
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/http_helper.py", line 88, in wrapper
    ret = func(self, *args)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/http_helper.py", line 59, in wrapper
    ret = func(self, *args)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/images.py", line 79, in put
    return self.send_data(self.request)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/images.py", line 116, in send_data
    request.method, imaged_url, headers, body, stream)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/images.py", line 186, in make_imaged_request
    raise exc.HTTPServiceUnavailable(s)
HTTPServiceUnavailable: Failed communicating with host: A Connection error occurred.
(Thread-154) INFO 2017-11-15 16:50:28,521 auth:278:root:(_decode_proxy_ticket) Proxy ticket valid: {u'iat': 1510757426, u'imaged-uri': u'https://storage-ge8-vdsm3.scl.lab.tlv.redhat.com:54322', u'nbf': 151075742
6, u'exp': 1510761026, u'transfer-ticket': u'2d27bb31-ad07-4e36-a6fc-c13f060106ae'}

Comment 1 Allon Mureinik 2017-11-19 09:03:02 UTC

Daniel/Idan - shouldn't this be solved as part of your current work?

Comment 2 Idan Shaby 2017-11-19 13:15:33 UTC

No, it doesn't seem to be related.
It should be fixed regardless.

Comment 3 Avihai 2017-11-28 12:15:23 UTC

Checked on ovirt-engine-4.2.0-0.0.master.20171124141652.gita5b4f9b.el7.centos.noarch .

- Cancle works good , good job! 
- Resume does not work , see errors below .

- > Do you want to open a new bug on this issue or reopen current bug ?

Errors see after Resume:

Engine proxy log:
(Thread-14792) INFO 2017-11-28 14:04:44,891 web:95:web:(log_start) START [10.35.4.172] OPTIONS /images/9bc8e944-d5e3-45b2-91a7-07d052702081
(Thread-14792) INFO 2017-11-28 14:04:44,895 web:102:web:(log_finish) FINISH [10.35.4.172] OPTIONS /images/9bc8e944-d5e3-45b2-91a7-07d052702081: [204] 0 (0.00s)
(Thread-14793) INFO 2017-11-28 14:04:44,912 web:95:web:(log_start) START [10.35.4.172] PUT /images/9bc8e944-d5e3-45b2-91a7-07d052702081
(Thread-14793) ERROR 2017-11-28 14:04:44,922 auth:312:root:(_decode_ovirt_ticket) Failed to verify proxy ticket: Ticket life time expired
(Thread-14793) ERROR 2017-11-28 14:04:44,926 auth:131:root:(start_session) Error starting session: Unable to verify proxy ticket
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 129, in start_session
    session_id = _create_update_session(ticket, session_id)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 192, in _create_update_session
    ticket_vars = _decode_proxy_ticket(authorization)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 235, in _decode_proxy_ticket
    payload = _decode_ovirt_ticket(ticket)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 313, in _decode_ovirt_ticket
    raise ValueError("Unable to verify proxy ticket")
ValueError: Unable to verify proxy ticket
(Thread-14793) WARNING 2017-11-28 14:04:44,936 web:112:web:(log_error) ERROR [10.35.4.172] PUT /images/9bc8e944-d5e3-45b2-91a7-07d052702081: [401] Could not initialize session: Unable to verify proxy ticket (0.03s)
(Thread-14794) INFO 2017-11-28 14:04:47,979 web:95:web:(log_start) START [10.35.4.172] PUT /images/9bc8e944-d5e3-45b2-91a7-07d052702081
(Thread-14794) ERROR 2017-11-28 14:04:47,986 auth:312:root:(_decode_ovirt_ticket) Failed to verify proxy ticket: Ticket life time expired
(Thread-14794) ERROR 2017-11-28 14:04:47,987 auth:131:root:(start_session) Error starting session: Unable to verify proxy ticket
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 129, in start_session
    session_id = _create_update_session(ticket, session_id)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 192, in _create_update_session
    ticket_vars = _decode_proxy_ticket(authorization)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 235, in _decode_proxy_ticket
    payload = _decode_ovirt_ticket(ticket)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 313, in _decode_ovirt_ticket
    raise ValueError("Unable to verify proxy ticket")
ValueError: Unable to verify proxy ticket
(Thread-14794) WARNING 2017-11-28 14:04:47,988 web:112:web:(log_error) ERROR [10.35.4.172] PUT /images/9bc8e944-d5e3-45b2-91a7-07d052702081: [401] Could not initialize session: Unable to verify proxy ticket (0.01s)
(Thread-14795) INFO 2017-11-28 14:04:51,014 web:95:web:(log_start) START [10.35.4.172] PUT /images/9bc8e944-d5e3-45b2-91a7-07d052702081
(Thread-14795) ERROR 2017-11-28 14:04:51,018 auth:312:root:(_decode_ovirt_ticket) Failed to verify proxy ticket: Ticket life time expired
(Thread-14795) ERROR 2017-11-28 14:04:51,019 auth:131:root:(start_session) Error starting session: Unable to verify proxy ticket
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 129, in start_session
    session_id = _create_update_session(ticket, session_id)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 192, in _create_update_session
    ticket_vars = _decode_proxy_ticket(authorization)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 235, in _decode_proxy_ticket
    payload = _decode_ovirt_ticket(ticket)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/auth.py", line 313, in _decode_ovirt_ticket
    raise ValueError("Unable to verify proxy ticket")
ValueError: Unable to verify proxy ticket
(Thread-14795) WARNING 2017-11-28 14:04:51,019 web:112:web:(log_error) ERROR [10.35.4.172] PUT /images/9bc8e944-d5e3-45b2-91a7-07d052702081: [401] Could not initialize session: Unable to verify proxy ticket (0.01s)

VDSM image proxy log:
2017-11-28 14:04:42,426 INFO    (ticket.server) [web] START [/] PATCH /tickets/9bc8e944-d5e3-45b2-91a7-07d052702081
2017-11-28 14:04:42,428 WARNING (ticket.server) [web] ERROR [/] PATCH /tickets/9bc8e944-d5e3-45b2-91a7-07d052702081: [404] No such ticket: 9bc8e944-d5e3-45b2-91a7-07d052702081 (0.00s)
2017-11-28 14:04:52,534 INFO    (ticket.server) [web] START [/] PATCH /tickets/9bc8e944-d5e3-45b2-91a7-07d052702081
2017-11-28 14:04:52,536 WARNING (ticket.server) [web] ERROR [/] PATCH /tickets/9bc8e944-d5e3-45b2-91a7-07d052702081: [404] No such ticket: 9bc8e944-d5e3-45b2-91a7-07d052702081 (0.00s)
2017-11-28 14:04:52,631 INFO    (ticket.server) [web] START [/] GET /tickets/9bc8e944-d5e3-45b2-91a7-07d052702081
2017-11-28 14:04:52,632 WARNING (ticket.server) [web] ERROR [/] GET /tickets/9bc8e944-d5e3-45b2-91a7-07d052702081: [404] No such ticket u'9bc8e944-d5e3-45b2-91a7-07d052702081' (0.00s)

VDSM:
2017-11-28 14:04:52,641+0200 ERROR (jsonrpc/3) [storage.Dispatcher] FINISH get_image_ticket error=Image daemon request failed: u"status=404, code=404, title=Not Found, explanation=The resource could not be found
., detail=No such ticket u'9bc8e944-d5e3-45b2-91a7-07d052702081', reason=Not Found" (dispatcher:82)

Comment 4 Idan Shaby 2017-11-28 12:31:06 UTC

Hi Avihai,

You can't resume a transfer (upload or download) after rebooting the daemon.
This is not a bug, it's the design.
In case that the daemon is restarted, the tickets are lost and therefore your only option is to start a new transfer.

Comment 5 Avihai 2017-11-29 05:42:23 UTC

(In reply to Idan Shaby from comment #4)
> Hi Avihai,
> 
> You can't resume a transfer (upload or download) after rebooting the daemon.
> This is not a bug, it's the design.
> In case that the daemon is restarted, the tickets are lost and therefore
> your only option is to start a new transfer.

 Ok, in that case I would expect that UI will no give me the option to resume at all right-> UI bug/RFE.

Anyway , this bug is verified on:
ovirt-engine-4.2.0-0.0.master.20171124141652.gita5b4f9b.el7.centos.noarch .

Comment 6 Sandro Bonazzola 2017-12-20 11:19:16 UTC

This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017.

Since the problem described in this bug report should be
resolved in oVirt 4.2.0 release, published on Dec 20th 2017, it has been closed with a resolution of CURRENT RELEASE.

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

Note You need to log in before you can comment on or make changes to this bug.