Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1523203

Summary: ImageIO- upload pause cause nasty log ERROR in both Engine image-proxy.log & in VDSM host daemon.log
Product: [oVirt] ovirt-imageio Reporter: Avihai <aefrat>
Component: DaemonAssignee: Idan Shaby <ishaby>
Status: CLOSED CURRENTRELEASE QA Contact: Avihai <aefrat>
Severity: medium Docs Contact:
Priority: high    
Version: ---CC: aefrat, amureini, bugs, derez, ebenahar, ishaby, lveyde, nsoffer, tnisan, ylavi
Target Milestone: ovirt-4.2.2Flags: rule-engine: ovirt-4.2+
ylavi: exception+
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 4.2.2 RC5, imageio v1.2.2 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-04-05 09:39:20 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:
Description Flags
engine , vdsm ,image_proxy,image_demon logs
none
engine , image_proxy ,vdsm,deamon logs none

Description Avihai 2017-12-07 11:54:57 UTC
Created attachment 1364288 [details]
engine , vdsm ,image_proxy,image_demon logs

Description of problem:
upload pause causes nasty log ERROR in both VDSM host deamon.log & engine proxy log.
If this is indeed not an error but expected please change it to an informative INFO message.

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


How reproducible:
100%

Steps to Reproduce:
1.Start disk upload via UI/SDK
2.Pause disk upload

Actual results:
Nasty errors appear in Engine image-proxy.log & in VDSM host daemon.log :

Engine image-proxy.log:
(Thread-8  ) ERROR 2017-12-07 11:24:15,311 web:89:web:(log_response) 10.35.4.169 - PUT  500 253 (3.44s)
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 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 370, in send
    timeout=timeout
  File "/usr/lib/python2.7/site-packages/urllib3/connectionpool.py", line 544, in urlopen
    body=body, headers=headers)
  File "/usr/lib/python2.7/site-packages/urllib3/connectionpool.py", line 349, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib64/python2.7/httplib.py", line 1017, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib64/python2.7/httplib.py", line 1051, in _send_request
    self.endheaders(body)
  File "/usr/lib64/python2.7/httplib.py", line 1013, in endheaders
    self._send_output(message_body)
  File "/usr/lib64/python2.7/httplib.py", line 868, in _send_output
    self.send(message_body)
  File "/usr/lib64/python2.7/httplib.py", line 838, in send
    datablock = data.read(blocksize)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/web.py", line 171, in read
    chunk = self.input_stream.read(to_read)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1528, in readinto
    + "(%d more bytes were expected)" % self.remaining
DisconnectionError: The client disconnected while sending the POST/PUT body (64487424 more bytes were expected)

VDSM host proxy log output:
2017-12-07 11:24:11,886 INFO    (Thread-7) [images] Writing 104857600 bytes at offset 629145600 to /rhev/data-center/mnt/blockSD/5820c57b-a8fb-4169-9b08-bcf28753c4f6/images/a000ecda-7c44-4325-99c7-92f711c92a27/4
ce89e2b-c750-4d3d-8c7f-ff58e5569d48 for ticket bff55936-d7d9-4bb1-aec2-5176b1250a75
2017-12-07 11:24:15,355 ERROR   (Thread-7) [web] 10.35.161.118 - PUT /bff55936-d7d9-4bb1-aec2-5176b1250a75 500 213 (3.46s)
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_daemon/server.py", line 162, in put
    op.run()
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/directio.py", line 72, in run
    self._run()
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/directio.py", line 160, in _run
    self._receive_chunk(dst, buf, count)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/directio.py", line 196, in _receive_chunk
    raise errors.PartialContent(self.size, self.done)
PartialContent: Requested 104857600 bytes, available 40370176 bytes


Expected results:


Additional info:

Comment 1 Idan Shaby 2018-01-24 10:14:25 UTC
Avihai, I couldn't reproduce the error that you got in the proxy's log.
Can you please see if you still get that error?

Comment 2 Avihai 2018-01-31 10:38:47 UTC
I checked at 4.2.1.3-0.1.el7 & issue looks fixed (exception is not seen)

Comment 3 Avihai 2018-01-31 11:02:47 UTC
(In reply to Avihai from comment #2)
> I checked at 4.2.1.3-0.1.el7 & issue looks fixed (exception is not seen)

Sorry, disregard the last remark as it was for another bug (1534444).

This issue does reproduce on 4.2.1.3-0.1.el7 with cancel upload scenario .

See logs attach.

Comment 4 Avihai 2018-01-31 11:04:21 UTC
Created attachment 1388906 [details]
engine , image_proxy ,vdsm,deamon logs

See the last line in image_proxy.log :
(Thread-793) ERROR 2018-01-31 12:25:04,779 web:112:web:(log_error) ERROR [10.35.206.23] PUT /images/cfb9b88f-574b-44c7-be01-75d5a5fa4dac: [500] The client disconnected while sending the POST/PUT body (94699520 more bytes were expected) (29.17s)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/web.py", line 64, in __call__
    resp = self.dispatch(request)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/web.py", line 91, in dispatch
    return method(*match.groups())
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/http_helper.py", line 104, in wrapper
    return func(self, *args)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/http_helper.py", line 60, in wrapper
    ret = func(self, *args)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/images.py", line 97, in put
    self.request.method, imaged_url, headers, body, stream)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_proxy/images.py", line 134, 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 370, in send
    timeout=timeout
  File "/usr/lib/python2.7/site-packages/urllib3/connectionpool.py", line 544, in urlopen
    body=body, headers=headers)
  File "/usr/lib/python2.7/site-packages/urllib3/connectionpool.py", line 349, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib64/python2.7/httplib.py", line 1017, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib64/python2.7/httplib.py", line 1051, in _send_request
    self.endheaders(body)
  File "/usr/lib64/python2.7/httplib.py", line 1013, in endheaders
    self._send_output(message_body)
  File "/usr/lib64/python2.7/httplib.py", line 868, in _send_output
    self.send(message_body)
  File "/usr/lib64/python2.7/httplib.py", line 838, in send
    datablock = data.read(blocksize)
  File "/usr/lib/python2.7/site-packages/ovirt_imageio_common/web.py", line 194, in read
    chunk = self.input_stream.read(to_read)
  File "/usr/lib/python2.7/site-packages/webob/request.py", line 1528, in readinto
    + "(%d more bytes were expected)" % self.remaining
DisconnectionError: The client disconnected while sending the POST/PUT body (94699520 more bytes were expected)

Comment 5 Idan Shaby 2018-01-31 12:17:50 UTC
OK, was it an upload flow via webadmin + cancel in the middle?

Comment 6 Avihai 2018-01-31 12:57:43 UTC
(In reply to Idan Shaby from comment #5)
> OK, was it an upload flow via webadmin + cancel in the middle?

Yes, start upload disk, wait until you see upload progress bar & than cancel.

Comment 7 Idan Shaby 2018-02-01 14:37:23 UTC
I still cannot reproduce it on latest engine-vdsm-daemon-proxy (master).
Are you using the latest versions of all the above?

Comment 8 RHV bug bot 2018-02-16 16:24:19 UTC
INFO: Bug status wasn't changed from MODIFIED to ON_QA due to the following reason:

[No relevant external trackers attached]

For more info please contact: infra

Comment 10 Idan Shaby 2018-02-25 11:50:30 UTC
Indeed, thanks for noticing.

Comment 11 Avihai 2018-03-04 09:58:31 UTC
Hi Idan,

According to ovirt-Image-io webgit this bug will only be fixed in the next image-io build (1.2.2 I presume?) .


On current latest downstream build (4.2.2-4) the ovirt-Image-io proxy/deamon/common is 1.2.1 -> see link:
http://bob.eng.lab.tlv.redhat.com/builds/4.2/rhv-4.2.2-4/el7Server/noarch/


Please move bug to back to 'ON QA' until this fix is merged inserted to latest downstream.

Comment 12 Allon Mureinik 2018-03-04 10:44:44 UTC
The fix is in imageio, not the engine. Changing product/component automatically.

Comment 13 Nir Soffer 2018-03-04 12:46:19 UTC
Idan, didn't we disable the cancel button during upload? This bug seems to happen
only when using this option.

Comment 14 Idan Shaby 2018-03-04 13:05:03 UTC
No, we disabled it during image download to fix Bug 1540539.

Comment 15 Sandro Bonazzola 2018-03-16 15:14:38 UTC
No build has been issued for 4.2.2 RC4, please build ASAP for having it included in 4.2.2 GA

Comment 16 Idan Shaby 2018-03-18 06:26:18 UTC
Daniel, will you make it to build image-io?

Comment 17 Daniel Erez 2018-03-18 13:13:15 UTC
(In reply to Idan Shaby from comment #16)
> Daniel, will you make it to build image-io?

Yes, imageio 1.2.2 should be released soon.

Comment 18 Avihai 2018-04-04 11:34:16 UTC
Verified on :
ovirt-engine 4.2.2.6-0.1.el7
ovirt-imageio-daemon-1.2.2-0.el7ev.noarch

Comment 19 Sandro Bonazzola 2018-04-05 09:39:20 UTC
This bugzilla is included in oVirt 4.2.2 release, published on March 28th 2018.

Since the problem described in this bug report should be
resolved in oVirt 4.2.2 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.