Bug 1613399
| Summary: | StreamingAPI - Transfer download disks via API fails to Get request to imagetransfers with HTTP/1.1 404 Not Found at the end of the transfer | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Avihai <aefrat> | ||||||||||
| Component: | BLL.Storage | Assignee: | Daniel Erez <derez> | ||||||||||
| Status: | CLOSED NOTABUG | QA Contact: | Elad <ebenahar> | ||||||||||
| Severity: | high | Docs Contact: | |||||||||||
| Priority: | unspecified | ||||||||||||
| Version: | 4.2.6.1 | CC: | aefrat, bugs, derez, frolland, ybenshim | ||||||||||
| Target Milestone: | --- | Keywords: | Automation, AutomationBlocker | ||||||||||
| Target Release: | --- | ||||||||||||
| Hardware: | Unspecified | ||||||||||||
| OS: | Unspecified | ||||||||||||
| Whiteboard: | |||||||||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||||||||
| Doc Text: | Story Points: | --- | |||||||||||
| Clone Of: | Environment: | ||||||||||||
| Last Closed: | 2018-08-19 13:34:09 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: | |||||||||||||
| Attachments: |
|
||||||||||||
Created attachment 1473999 [details]
2nd test that failed logs - glusterfs
Proxy/deamon versions: ovirt-imageio-proxy-1.4.2-0.el7ev.noarch ovirt-imageio-daemon-1.4.2-0.el7ev.noarch ovirt-imageio-common-1.4.2-0.el7ev.noarch Created attachment 1474001 [details]
imageio proxy and deamon logs
Daniel, can you take a look? Thanks. @Avihai - I couldn't find the relevant transfer id in the daemon/proxy logs. Can you please send the daemon log of the relevant host? Also, are you using transfer_url or poxy_url in the tests? Also, are you using transfer_url or poxy_url in the tests? I use proxy_url. Focusing one of the transfer that got 404 : Image -id = 86838f50-5255-4589-bc1e-f987b14ed1e6 Ticket id = 0ad2c5fd-fca5-456d-be6c-5220cbb5570e Relevant logs(engine/vdsm) to the timeframe I used in the scenario can be found in attached 'logs of issue with nfs' Proxy log that are attach does contain the relevant image-id/ticket-id(see below) I added the relevant daemon log that shows the relevant image-id '86838f50-5255-4589-bc1e-f987b14ed1e6' but for some reason not the relevant Ticket id for some reason. Art.log: 2018-08-07 07:32:04,454 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Location: https://hosted-engine-06.lab.eng.tlv2.redhat.com/ovirt-engine/api/v4/ovirt-engine/api/im agetransfers/0ad2c5fd-fca5-456d-be6c-5220cbb5570e 2018-08-07 07:32:09,686 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < GET /ovirt-engine/api/imagetransfers/0ad2c5fd-fca5-456d-be6c-5220cbb5570e HTTP/1.1 2018-08-07 07:32:09,686 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Host: hosted-engine-06.lab.eng.tlv2.redhat.com 2018-08-07 07:32:09,687 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < User-Agent: PythonSDK/4.2.7 2018-08-07 07:32:09,687 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Version: 4 2018-08-07 07:32:09,687 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Content-Type: application/xml 2018-08-07 07:32:09,687 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Accept: application/xml 2018-08-07 07:32:09,687 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Authorization: Bearer Gl6uv_wyKyo-jjDIqmmN8m6zvhkwia_OwyLriRwOVSak1ohWO22jx-SvM5hC4Gjh6MC_remg9ylv O1swEXriHA 2018-08-07 07:32:09,741 - ThreadPoolExecutor-202_0 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > HTTP/1.1 404 Not Found 07:32:04 2018-08-07 07:32:03,916 INFO Test Step 22: Download image id 86838f50-5255-4589-bc1e-f987b14ed1e6 Engine log 2018-08-07 07:32:04,428+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-32) [c9381e02-7b72-4a36-921a-f4ab3886e724] Updating image transfer 0ad2c5fd-fca5-456d-be6c-5220c bb5570e (image 86838f50-5255-4589-bc1e-f987b14ed1e6) phase to Transferring 2018-08-07 07:32:04,429+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (default task-32) [c9381e02-7b72-4a36-921a-f4ab3886e724] Returning from proceedCommandExecution after star ting transfer session for image transfer command '0ad2c5fd-fca5-456d-be6c-5220cbb5570e' 2018-08-07 07:32:04,440+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (default task-46) [e1d767f7-6e73-4a2d-9e2a-2373b30bdddd] Lock Acquired to object 'EngineLock:{exclusiveLoc ks='', sharedLocks='[16fa5b61-435f-4b23-8c02-772ba414e01a=DISK]'}' 2018-08-07 07:32:04,441+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-32) [c9381e02-7b72-4a36-921a-f4ab3886e724] EVENT_ID: TRANSFER_IMAGE_INITIATED(1,031), Image Download with disk disk_virtioraw_0707302684 was initiated by admin@internal-authz. 2018-08-07 07:32:04,504+03 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-40) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2018-08-07 07:32:04,512+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (default task-46) [e1d767f7-6e73-4a2d-9e2a-2373b30bdddd] Running command: TransferDiskImageCommand internal: false. Entities affected : ID: 16fa5b61-435f-4b23-8c02-772ba414e01a Type: DiskAction group EDIT_DISK_PROPERTIES with role type USER 2018-08-07 07:32:04,512+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (default task-46) [e1d767f7-6e73-4a2d-9e2a-2373b30bdddd] Creating ImageTransfer entity for command 'bbcd3b95-fce5-4f94-93c2-0f350b066d16' 2018-08-07 07:32:04,566+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (default task-46) [e1d767f7-6e73-4a2d-9e2a-2373b30bdddd] START, GetVolumeInfoVDSCommand(HostName = host_mixed_2, GetVolumeInfoVDSCommandParameters:{hostId='c20cb752-9b83-4690-8b13-e196c6cb0910', storagePoolId='0ecf2116-9999-11e8-926c-001a4a168bfc', storageDomainId='2aabeccd-d195-4262-9612-8cd0966c8d08', imageGroupId='16fa5b61-435f-4b23-8c02-772ba414e01a', imageId='ab2780ac-cd03-4b31-a0eb-ea4aa444218c'}), log id: 2cf54982 2018-08-07 07:32:04,570+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferImageStatusCommand] (default task-52) [988ece8a-9096-4392-a595-56b525040259] Running command: TransferImageStatusCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_DISK with role type USER 2018-08-07 07:32:04,571+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (default task-52) [988ece8a-9096-4392-a595-56b525040259] Updating image transfer 0ad2c5fd-fca5-456d-be6c-5220cbb5570e (image 86838f50-5255-4589-bc1e-f987b14ed1e6) phase to Finalizing Success Proxy logs: Thread-81 ) INFO 2018-08-07 07:32:04,414 web:97:web:(__call__) START: [10.46.16.252] PUT /tickets/ (Thread-81 ) INFO 2018-08-07 07:32:04,415 auth:187:auth2:(add_signed_ticket) Adding new ticket: <Ticket id=u'0728ab8a-e247-481a-98ce-538c1034d966', url=u'https://lynx24.lab.eng.tlv2.redhat.com:54322' timeout=359 99.5841960907 at 0x7f04304d4a50> (Thread-81 ) INFO 2018-08-07 07:32:04,416 web:77:web:(close) FINISH [10.46.16.252] PUT /tickets/: [200] 0 [request=0.002356] (Thread-82 ) INFO 2018-08-07 07:32:04,679 web:97:web:(__call__) START: [10.46.16.252] DELETE /tickets/0728ab8a-e247-481a-98ce-538c1034d966 (Thread-82 ) INFO 2018-08-07 07:32:04,679 auth:201:auth2:(delete_ticket) Deleting ticket u'0728ab8a-e247-481a-98ce-538c1034d966' (Thread-82 ) INFO 2018-08-07 07:32:04,680 web:77:web:(close) FINISH [10.46.16.252] DELETE /tickets/0728ab8a-e247-481a-98ce-538c1034d966: [204] 0 [request=0.000857] (Thread-83 ) INFO 2018-08-07 07:32:04,772 web:97:web:(__call__) START: [10.46.16.252] PUT /tickets/ Deamon log: 2018-08-07 07:32:04,399 INFO (Thread-59) [web] START: [/] PUT /tickets/0728ab8a-e247-481a-98ce-538c1034d966 2018-08-07 07:32:04,400 INFO (Thread-59) [tickets] Adding ticket <Ticket active=False expires=4332565 filename=None idle_time=0 ops=[u'read'] size=1073741824 transferred=0 url=u'file:///rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21' uuid=u'0728ab8a-e247-481a-98ce-538c1034d966' at 0x7f95954b0690> 2018-08-07 07:32:04,401 INFO (Thread-59) [web] FINISH [/] PUT /tickets/0728ab8a-e247-481a-98ce-538c1034d966: [200] 0 [request=0.001583] 2018-08-07 07:32:04,667 INFO (Thread-60) [web] START: [/] DELETE /tickets/0728ab8a-e247-481a-98ce-538c1034d966 2018-08-07 07:32:04,668 INFO (Thread-60) [tickets] Removing ticket 0728ab8a-e247-481a-98ce-538c1034d966 2018-08-07 07:32:04,668 INFO (Thread-60) [web] FINISH [/] DELETE /tickets/0728ab8a-e247-481a-98ce-538c1034d966: [204] 0 [request=0.000791] 2018-08-07 07:32:04,759 INFO (Thread-61) [web] START: [/] PUT /tickets/057d4412-ff4a-461d-814c-67e4819c12a9 Created attachment 1474875 [details]
relevant deamon log
Still Focusing one of the transfer that got 404 :
Image -id = 86838f50-5255-4589-bc1e-f987b14ed1e6
Ticket id = 0ad2c5fd-fca5-456d-be6c-5220cbb5570e
I noticed I see the faulty Ticket-id(0ad2c5fd-fca5-456d-be6c-5220cbb5570e) only in engine/proxy/art logs but not in deamon log.
The matching image-id (86838f50-5255-4589-bc1e-f987b14ed1e6) is seen in all logs attached.
I hope this is enough .
You can see also the relevant imageid transfer at VDSM log:
test_floating_disks_matrix_downloads[nfs]]$ less hypervisor-lynx24_vdsm.log
2018-08-07 07:32:04,392+0300 INFO (jsonrpc/7) [vdsm.api] FINISH prepareImage return={'info': {'path': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612
-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'type': 'file'}, 'path': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aab
eccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'imgVolumesInfo': [{'domainID': '2aabeccd-d195-4262-9612-8cd0966c8d08', 'leaseOffset': 0, 'path
': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'vo
lumeID': u'aa987bdd-8524-4221-bdac-61b977bc4a21', 'leasePath': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-
bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21.lease', 'imageID': '86838f50-5255-4589-bc1e-f987b14ed1e6'}]} from=::ffff:10.46.16.252,34196, flow_id=c9381e02-7b72-4a36-921a-f4ab3886e724, task_id=c109d4fe-
748a-40ae-a474-79071cfd94fd (api:52)
2018-08-07 07:32:04,392+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] (Task='c109d4fe-748a-40ae-a474-79071cfd94fd') finished: {'info': {'path': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com
:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'type': 'file'}, 'path': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.
eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'imgVolumesInfo': [{'domainID': '2aabeccd-d195-426
2-9612-8cd0966c8d08', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1
e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'volumeID': u'aa987bdd-8524-4221-bdac-61b977bc4a21', 'leasePath': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262
-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21.lease', 'imageID': '86838f50-5255-4589-bc1e-f987b14ed1e6'}]} (task:1201)
2018-08-07 07:32:04,398+0300 INFO (jsonrpc/0) [vdsm.api] START add_image_ticket(ticket={'url': 'file:///rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'size': 1073741824, 'uuid': '0728ab8a-e247-481a-98ce-538c1034d966', 'timeout': 300, 'ops': ['read']}) from=::ffff:10.46.16.252,34196, flow_id=c9381e02-7b72-4a36-921a-f4ab3886e724, task_id=12762c03-f02b-49f5-97bb-099445ca3519 (api:46)
2018-08-07 07:32:04,398+0300 DEBUG (jsonrpc/0) [storage.imagetickets] Sending request method='PUT', ticket='0728ab8a-e247-481a-98ce-538c1034d966', body='{"url": "file:///rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21", "size": 1073741824, "uuid": "0728ab8a-e247-481a-98ce-538c1034d966", "timeout": 300, "ops": ["read"]}' (imagetickets:78)
(In reply to Avihai from comment #8) > Still Focusing one of the transfer that got 404 : > Image -id = 86838f50-5255-4589-bc1e-f987b14ed1e6 > Ticket id = 0ad2c5fd-fca5-456d-be6c-5220cbb5570e > > I noticed I see the faulty Ticket-id(0ad2c5fd-fca5-456d-be6c-5220cbb5570e) > only in engine/proxy/art logs but not in deamon log. I couldn't find this ticket-id in the attached proxy log. Can you please attach the latest one? > The matching image-id (86838f50-5255-4589-bc1e-f987b14ed1e6) is seen in all > logs attached. > > I hope this is enough . > > You can see also the relevant imageid transfer at VDSM log: > > test_floating_disks_matrix_downloads[nfs]]$ less hypervisor-lynx24_vdsm.log > > 2018-08-07 07:32:04,392+0300 INFO (jsonrpc/7) [vdsm.api] FINISH > prepareImage return={'info': {'path': > u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612 > -8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221- > bdac-61b977bc4a21', 'type': 'file'}, 'path': > u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aab > eccd-d195-4262-9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/ > aa987bdd-8524-4221-bdac-61b977bc4a21', 'imgVolumesInfo': [{'domainID': > '2aabeccd-d195-4262-9612-8cd0966c8d08', 'leaseOffset': 0, 'path > ': > u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50- > 5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'vo > lumeID': u'aa987bdd-8524-4221-bdac-61b977bc4a21', 'leasePath': > u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50- > 5255-4589- > bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21.lease', 'imageID': > '86838f50-5255-4589-bc1e-f987b14ed1e6'}]} from=::ffff:10.46.16.252,34196, > flow_id=c9381e02-7b72-4a36-921a-f4ab3886e724, task_id=c109d4fe- > 748a-40ae-a474-79071cfd94fd (api:52) > 2018-08-07 07:32:04,392+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] > (Task='c109d4fe-748a-40ae-a474-79071cfd94fd') finished: {'info': {'path': > u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com > :_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50- > 5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'type': > 'file'}, 'path': u'/rhev/data-center/mnt/mantis-nfs-lif2.lab. > eng.tlv2.redhat.com:_nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612- > 8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221- > bdac-61b977bc4a21', 'imgVolumesInfo': [{'domainID': '2aabeccd-d195-426 > 2-9612-8cd0966c8d08', 'leaseOffset': 0, 'path': > u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50- > 5255-4589-bc1e-f987b14ed1 > e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'volumeID': > u'aa987bdd-8524-4221-bdac-61b977bc4a21', 'leasePath': > u'/rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aabeccd-d195-4262 > -9612-8cd0966c8d08/images/86838f50-5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524- > 4221-bdac-61b977bc4a21.lease', 'imageID': > '86838f50-5255-4589-bc1e-f987b14ed1e6'}]} (task:1201) > > 2018-08-07 07:32:04,398+0300 INFO (jsonrpc/0) [vdsm.api] START > add_image_ticket(ticket={'url': > 'file:///rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50- > 5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21', 'size': > 1073741824, 'uuid': '0728ab8a-e247-481a-98ce-538c1034d966', 'timeout': 300, > 'ops': ['read']}) from=::ffff:10.46.16.252,34196, > flow_id=c9381e02-7b72-4a36-921a-f4ab3886e724, > task_id=12762c03-f02b-49f5-97bb-099445ca3519 (api:46) > 2018-08-07 07:32:04,398+0300 DEBUG (jsonrpc/0) [storage.imagetickets] > Sending request method='PUT', ticket='0728ab8a-e247-481a-98ce-538c1034d966', > body='{"url": > "file:///rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com: > _nas01_ge__5__nfs__0/2aabeccd-d195-4262-9612-8cd0966c8d08/images/86838f50- > 5255-4589-bc1e-f987b14ed1e6/aa987bdd-8524-4221-bdac-61b977bc4a21", "size": > 1073741824, "uuid": "0728ab8a-e247-481a-98ce-538c1034d966", "timeout": 300, > "ops": ["read"]}' (imagetickets:78) Yosi, please provide Daniel the info, thanks Hi, The logs that Avihai attached are from tier1 execution on rhv-4.2.6-1. Regarding the ticket-id from comment #9, it's: 0728ab8a-e247-481a-98ce-538c1034d966 and you can find it in "imageio proxy and deamon logs". While checking the logs I came across the next log for some image transfers: 2018-08-07 07:32:04,670+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [c9381e02-7b72-4a36-921a-f4ab3886e724] Successfully stopped image transfer session for ticket '0728ab8a-e247-481a-98ce-538c1034d966' It's part of the flow just before removing the ticket, right? (In reply to Yosi Ben Shimon from comment #11) > Hi, > The logs that Avihai attached are from tier1 execution on rhv-4.2.6-1. > Regarding the ticket-id from comment #9, it's: > 0728ab8a-e247-481a-98ce-538c1034d966 and you can find it in "imageio proxy > and deamon logs". According the engine log, this one has been finished successfully: 2018-08-07 07:32:04,663+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [c9381e02-7b72-4a36-921a-f4ab3886e724] Finalizing successful transfer for Download disk 'disk_virtioraw_0707302684' (disk id: '86838f50-5255-4589-bc1e-f987b14ed1e6', image id: 'aa987bdd-8524-4221-bdac-61b977bc4a21') 2018-08-07 07:32:04,665+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [c9381e02-7b72-4a36-921a-f4ab3886e724] START, RemoveImageTicketVDSCommand(HostName = host_mixed_3, RemoveImageTicketVDSCommandParameters:{hostId='25a3b804-a8ee-44ba-8f2f-e0928778f2ce', ticketId='0728ab8a-e247-481a-98ce-538c1034d966', timeout='null'}), log id: ceeaf3e > > While checking the logs I came across the next log for some image transfers: > 2018-08-07 07:32:04,670+03 INFO > [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] > (EE-ManagedThreadFactory-engineScheduled-Thread-28) > [c9381e02-7b72-4a36-921a-f4ab3886e724] Successfully stopped image transfer > session for ticket '0728ab8a-e247-481a-98ce-538c1034d966' > > It's part of the flow just before removing the ticket, right? Indeed, we the ticket is removed after finishing the upload. Daniel, the issue here is the HTTP 404 Not Found response issue is seen at 2018-08-07 07:32:10 which fails the test AFTER download image is complete. There is no other log that is missing here. I am aware that apparently there is nothing wrong seen in all other logs (Engine/VDSM/proxy/daemon) except for the art.log which describes HTTP request/response flow during the test. The question is why do we see HTTP/1.1 404 Not Found? These errors appear AFTER (6 seconds) the transfer was finished successfully (which was at 2018-08-07 07:32:04), maybe this has something to do with the Teardown process of the ticket after it's finished? GET request: 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < GET /ovirt-engine/api/imagetransfers/c468e63e-4e5c-408f-9de0-43ba4a433971 HTTP/1.1 GET response is: 2018-08-07 07:32:10,160 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > HTTP/1.1 404 Not Found Also, more info that maybe shed some light on this issue :
I had permission issues with the folder I was downloading the images to ( os.path.expanduser('~/download/')) which was fixed in a patch https://code.engineering.redhat.com/gerrit/#/c/146582 .
This means that the download ticket cycle (Creation -> Transfer -> finished -> finalize successfully) BUT the image data itself was not downloaded as open a file for writing fails w/o proper permissions
From SDK download example (https://github.com/oVirt/ovirt-engine-sdk/blob/master/sdk/examples/download_disk.py line 141) :
> with open(path, "wb") as mydisk:
As without write permission, this will fail but the ticket cycle finished successfully.
I think this is what happened here which failed the downloads, however, this does not explain the HTTP 404 response :(
(In reply to Avihai from comment #14) > Also, more info that maybe shed some light on this issue : > > I had permission issues with the folder I was downloading the images to ( > os.path.expanduser('~/download/')) which was fixed in a patch > https://code.engineering.redhat.com/gerrit/#/c/146582 . > > This means that the download ticket cycle (Creation -> Transfer -> finished > -> finalize successfully) BUT the image data itself was not downloaded as > open a file for writing fails w/o proper permissions > > From SDK download example > (https://github.com/oVirt/ovirt-engine-sdk/blob/master/sdk/examples/ > download_disk.py line 141) : > > > with open(path, "wb") as mydisk: > > As without write permission, this will fail but the ticket cycle finished > successfully. > > I think this is what happened here which failed the downloads, however, this > does not explain the HTTP 404 response :( So it doesn't reproduce now that the permissions issue is fixed? Can it perhaps be reproduced with a simple sdk script of a single download to a folder without permissions? I'll check it out and update w/wo permissions. So far running the test with permissions once & the issue did not reproduce. Trying now for the 2nd time with permissions & than will run once w/o permissions and will update. It looks like read-only permissions on this directory
('chmod 444 <download_dir>' for example) cause this issue to reproduce.
With my latest patch that gives full permissions on the download directory, this issue does not reproduce.
My theory:
As download start & end really fast as no actual download occurs the GET request for the transfer that already ended gives HTTP 404 Not Found as the transfer ended already.
What do you think ?
(In reply to Avihai from comment #17) > It looks like read-only permissions on this directory > ('chmod 444 <download_dir>' for example) cause this issue to reproduce. > > With my latest patch that gives full permissions on the download directory, > this issue does not reproduce. > > My theory: > As download start & end really fast as no actual download occurs the GET > request for the transfer that already ended gives HTTP 404 Not Found as the > transfer ended already. > > What do you think ? I've tried the following test with a simple sdk script: 1. created 'test' folder 2. chmod -w test 3. ./download_disk.py 6e7619d5-d5db-4278-8a6e-921d565d84f9 Traceback (most recent call last): File "./download_disk.py", line 108, in <module> with open(path, "wb") as mydisk: IOError: [Errno 13] Permission denied: 'test/disk.qcow2' * in proxy log: 10.35.0.193 - - [19/Aug/2018 15:24:06] "DELETE /tickets/0d5d3650-0a48-4a15-b0de-a8710b37affc HTTP/1.1" 204 0 So the basic (negative) flow seems to behave correctly. Maybe to 404 error was just some race issue in the test env.. Any way, doesn't seem to be too relevant unless you can reproduce it in a simple sdk script? (In reply to Daniel Erez from comment #18) > (In reply to Avihai from comment #17) > > It looks like read-only permissions on this directory > > ('chmod 444 <download_dir>' for example) cause this issue to reproduce. > > > > With my latest patch that gives full permissions on the download directory, > > this issue does not reproduce. > > > > My theory: > > As download start & end really fast as no actual download occurs the GET > > request for the transfer that already ended gives HTTP 404 Not Found as the > > transfer ended already. > > > > What do you think ? > > I've tried the following test with a simple sdk script: > 1. created 'test' folder > 2. chmod -w test > 3. ./download_disk.py 6e7619d5-d5db-4278-8a6e-921d565d84f9 > Traceback (most recent call last): > File "./download_disk.py", line 108, in <module> > with open(path, "wb") as mydisk: > IOError: [Errno 13] Permission denied: 'test/disk.qcow2' > * in proxy log: 10.35.0.193 - - [19/Aug/2018 15:24:06] "DELETE > /tickets/0d5d3650-0a48-4a15-b0de-a8710b37affc HTTP/1.1" 204 0 > > So the basic (negative) flow seems to behave correctly. Maybe to 404 error > was just some race issue in the test env.. Any way, doesn't seem to be too > relevant unless you can reproduce it in a simple sdk script? In my download script used in automation, I added some debug info in the form of : 'transfer_service.get()' during/after the transfer finalization stage as I wanted to test the stages are correct during those stages. Those transfer_service.get() commands are the root cause of this bug as if they are done after several seconds delay after the transfer is completed you will get the 404 Error. --> 165 transfer = transfer_service.get() 166 print "%s transfer phase is %s" % (timestamp, transfer.phase) ipdb> transfer_service.get() <ovirtsdk4.types.ImageTransfer object at 0x7fb794ae1550> ipdb> transfer_service.get() <ovirtsdk4.types.ImageTransfer object at 0x7fb794ae15d0> ipdb> transfer_service.get() <ovirtsdk4.types.ImageTransfer object at 0x7fb794ae1590> ipdb> transfer_service.get() <ovirtsdk4.types.ImageTransfer object at 0x7fb794ae1610> ipdb> transfer_service.get() <ovirtsdk4.types.ImageTransfer object at 0x7fb794ae1550> ipdb> transfer_service.get() <ovirtsdk4.types.ImageTransfer object at 0x7fb794ae15d0> ipdb> transfer_service.get() <ovirtsdk4.types.ImageTransfer object at 0x7fb794ae1690> ipdb> transfer_service.get() *** NotFoundError: HTTP response code is 404. I saw that in the official example this transfer_service.get() only appears in INITIALIZING stage , this is why you do not see this issue. In short I'm closing this bug as NOTABUG as this is an automation code + timing that is the root cause here . |
Created attachment 1473998 [details] logs of issue with nfs Description of problem: Tier1 download tests failed download with HTTP/1.1 404 error to Get request to imagetransfers at the end of the disks download. This issue is seen only at RESTAPI (request/respnse ) art.log (see below) This occurred in 3/4 disk download tests. No issues/ERRORs are seen at engine/proxy/deamon log .( see attached logs) The error is seen in art (RESTAPI) log : 2018-08-07 07:32:10,078 - ThreadPoolExecutor-202_1 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Connection #108 to host hosted-engine-06.lab.eng.tlv2.redhat.com left intact 2018-08-07 07:32:10,101 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Found bundle for host hosted-engine-06.lab.eng.tlv2.redhat.com: 0x7f1a8c6bb390 2018-08-07 07:32:10,101 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Connection 103 seems to be dead! 2018-08-07 07:32:10,101 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Closing connection 103 2018-08-07 07:32:10,101 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * About to connect() to hosted-engine-06.lab.eng.tlv2.redhat.com port 443 (#109) 2018-08-07 07:32:10,101 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Trying 10.46.16.252... 2018-08-07 07:32:10,102 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Connected to hosted-engine-06.lab.eng.tlv2.redhat.com (10.46.16.252) port 443 (#109) 2018-08-07 07:32:10,102 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * CAfile: /var/lib/jenkins/workspace/rhv-4.2-ge-runner-tier1/ca.crt 2018-08-07 07:32:10,103 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * CApath: none 2018-08-07 07:32:10,104 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * SSL connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 2018-08-07 07:32:10,104 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Server certificate: 2018-08-07 07:32:10,104 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * subject: CN=hosted-engine-06.lab.eng.tlv2.redhat.com,O=localdomain,C=US 2018-08-07 07:32:10,104 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * start date: Aug 05 16:51:20 2018 GMT 2018-08-07 07:32:10,104 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * expire date: Jul 11 16:51:20 2023 GMT 2018-08-07 07:32:10,104 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * common name: hosted-engine-06.lab.eng.tlv2.redhat.com 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * issuer: CN=hosted-engine-06.lab.eng.tlv2.redhat.com.34816,O=localdomain,C=US 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < GET /ovirt-engine/api/imagetransfers/c468e63e-4e5c-408f-9de0-43ba4a433971 HTTP/1.1 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Host: hosted-engine-06.lab.eng.tlv2.redhat.com 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < User-Agent: PythonSDK/4.2.7 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Version: 4 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Content-Type: application/xml 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Accept: application/xml 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Authorization: Bearer rzJaRrToW3hahyDviu5JhC7c6aBs5BwmhXn_bRp4qUsXgpw-GDvfaya1besNcrW2Kio2e7odpH2dACJyua1HXQ 2018-08-07 07:32:10,160 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > HTTP/1.1 404 Not Found 2018-08-07 07:32:10,161 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Date: Tue, 07 Aug 2018 04:32:10 GMT 2018-08-07 07:32:10,161 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Server: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips 2018-08-07 07:32:10,161 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Content-Length: 0 2018-08-07 07:32:10,161 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Correlation-Id: 539dd1d4-0942-4309-90e8-fbe92b3ad36a 2018-08-07 07:32:10,161 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > 2018-08-07 07:32:10,161 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Connection #109 to host hosted-engine-06.lab.eng.tlv2.redhat.com left intact 2018-08-07 07:32:10,172 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Found bundle for host hosted-engine-06.lab.eng.tlv2.redhat.com: 0x7f1a98fdad80 2018-08-07 07:32:10,172 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Connection 105 seems to be dead! 2018-08-07 07:32:10,172 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Closing connection 105 2018-08-07 07:32:10,172 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * About to connect() to hosted-engine-06.lab.eng.tlv2.redhat.com port 443 (#110) 2018-08-07 07:32:10,173 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Trying 10.46.16.252... 2018-08-07 07:32:10,173 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Connected to hosted-engine-06.lab.eng.tlv2.redhat.com (10.46.16.252) port 443 (#110) 2018-08-07 07:32:10,174 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * CAfile: /var/lib/jenkins/workspace/rhv-4.2-ge-runner-tier1/ca.crt 2018-08-07 07:32:10,174 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * CApath: none 2018-08-07 07:32:10,175 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * SSL connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 2018-08-07 07:32:10,175 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Server certificate: 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * subject: CN=hosted-engine-06.lab.eng.tlv2.redhat.com,O=localdomain,C=US 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * start date: Aug 05 16:51:20 2018 GMT 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * expire date: Jul 11 16:51:20 2023 GMT 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * common name: hosted-engine-06.lab.eng.tlv2.redhat.com 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * issuer: CN=hosted-engine-06.lab.eng.tlv2.redhat.com.34816,O=localdomain,C=US 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < GET /ovirt-engine/api/imagetransfers/5aa13406-fe02-4f68-b19c-ecbc12c2e305 HTTP/1.1 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Host: hosted-engine-06.lab.eng.tlv2.redhat.com 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < User-Agent: PythonSDK/4.2.7 2018-08-07 07:32:10,176 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Version: 4 2018-08-07 07:32:10,177 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Content-Type: application/xml 2018-08-07 07:32:10,177 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Accept: application/xml 2018-08-07 07:32:10,177 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < Authorization: Bearer lGX67jloEQkHPkihs4qXrImbJUMQ1OMqYkhTvXee_ZcbxSvX-dAaxyDmMfzZLTIOZpvhVkYslbRqyQpaOE3PMA 2018-08-07 07:32:10,231 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > HTTP/1.1 404 Not Found 2018-08-07 07:32:10,231 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Date: Tue, 07 Aug 2018 04:32:10 GMT 2018-08-07 07:32:10,231 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Server: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips 2018-08-07 07:32:10,231 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Content-Length: 0 2018-08-07 07:32:10,231 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > Correlation-Id: 82acc4ea-bc81-4cf8-89ee-0cbfd6e977c5 2018-08-07 07:32:10,231 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > 2018-08-07 07:32:10,232 - ThreadPoolExecutor-202_3 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - * Connection #110 to host hosted-engine-06.lab.eng.tlv2.redhat.com left intact 2018-08-07 07:32:10,306 - MainThread - art.logging - ERROR - Status: failed Version-Release number of selected component (if applicable): 4.2.6_SNAPSHOT-84.gad3de30.0.scratch.master.el7ev How reproducible: 3 out of 4 download tests (ISCSI/NFS/Gluster storage types) Steps to Reproduce: 07:29:31 2018-08-07 07:29:30,923 INFO Test Setup 4: Creating VM vm_TestCase18258_0707293092 07:29:43 2018-08-07 07:29:43,439 INFO Test Setup 5: Start VM vm_TestCase18258_0707293092 07:29:43 2018-08-07 07:29:43,443 INFO Test Setup 6: [class] Start VM vm_TestCase18258_0707293092 with {'wait_for_ip': False, 'pause': False, 'use_cloud_init': False, 'timeout': 600, 'wait_for_status': 'up'} 07:30:14 2018-08-07 07:30:14,051 INFO Test Setup 7: Fetch VM vm_TestCase18258_0707293092 executor 07:30:26 2018-08-07 07:30:26,676 INFO Test Setup 8: Create disks with filesystem on VM vm_TestCase18258_0707293092 07:31:26 2018-08-07 07:31:26,537 INFO Test Setup 9: Create file on all the VM's vm_TestCase18258_0707293092 disks 07:31:27 2018-08-07 07:31:27,699 INFO Test Setup 10: Save file /mount-point_0707305766/test_file checksum value 07:31:29 2018-08-07 07:31:29,481 INFO Test Setup 11: Save file /mount-point_0707310660/test_file checksum value 07:31:31 2018-08-07 07:31:31,292 INFO Test Setup 12: Save file /mount-point_0707311536/test_file checksum value 07:31:33 2018-08-07 07:31:32,940 INFO Test Setup 13: Save file /mount-point_0707312417/test_file checksum value 07:31:34 2018-08-07 07:31:34,120 INFO Test Setup 14: Stop VM vm_TestCase18258_0707293092 07:31:34 2018-08-07 07:31:34,309 INFO Test Setup 15: [class] Stop vm vm_TestCase18258_0707293092 with {'async': 'true'} 07:31:36 2018-08-07 07:31:36,724 INFO Test Setup 16: detach disk disk_virtioraw_0707302684 07:31:37 2018-08-07 07:31:37,207 INFO Test Setup 17: detach disk disk_virtiocow_0707302684 07:31:37 2018-08-07 07:31:37,837 INFO Test Setup 18: detach disk disk_virtio_scsicow_0707302684 07:31:38 2018-08-07 07:31:38,149 INFO Test Setup 19: detach disk disk_virtio_scsiraw_0707302685 07:31:38 2018-08-07 07:31:38,461 INFO 312: storage/rhevmtests.storage.storage_streaming_api.test_download_image.TestCase18258.test_floating_disks_matrix_downloads[nfs] 07:31:38 2018-08-07 07:31:38,461 INFO STORAGE: NFS 07:31:38 2018-08-07 07:31:38,462 INFO Test Step 20: Check md5sums and sizes of disks ['disk_virtioraw_0707302684', 'disk_virtiocow_0707302684', 'disk_virtio_scsicow_0707302684', 'disk_virtio_scsiraw_0707302685'] pre download 07:32:03 2018-08-07 07:32:03,697 INFO Test Step 21: Starting parallel download of disks ['disk_virtioraw_0707302684', 'disk_virtiocow_0707302684', 'disk_virtio_scsicow_0707302684', 'disk_virtio_scsiraw_0707302685'] 07:32:04 2018-08-07 07:32:03,916 INFO Test Step 22: Download image id 86838f50-5255-4589-bc1e-f987b14ed1e6 07:32:04 2018-08-07 07:32:04,157 INFO Test Step 23: Download image id 16fa5b61-435f-4b23-8c02-772ba414e01a 07:32:04 2018-08-07 07:32:04,397 INFO Test Step 24: Download image id e149df17-0c9b-4354-8cba-8177bfe0612f 07:32:04 2018-08-07 07:32:04,673 INFO Test Step 25: Download image id 13c5150a-5358-48b2-8a6e-de9d58d9725c 07:32:10 2018-08-07 07:32:10,306 ERROR Result: FAILED 07:32:10 F2018-08-07 07:32:10,320 INFO ====================== Actual results: The download disks should not fail at any stage. Get request to imagetransfers failed with 04 Not Found 2018-08-07 07:32:10,105 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - < GET /ovirt-engine/api/imagetransfers/c468e63e-4e5c-408f-9de0-43ba4a433971 HTTP/1.1 2018-08-07 07:32:10,160 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > HTTP/1.1 404 Not Found response is: 2018-08-07 07:32:10,160 - ThreadPoolExecutor-202_2 - art.rhevm_api.tests_lib.low_level.streaming_api - DEBUG - > HTTP/1.1 404 Not Found Expected results: response should be 204 and download should not fail . Additional info: