RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1619805 - Log error response from oVirt server in rhv-upload-plugin
Summary: Log error response from oVirt server in rhv-upload-plugin
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: libguestfs
Version: 7.6
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: rc
: ---
Assignee: Richard W.M. Jones
QA Contact: Virtualization Bugs
URL:
Whiteboard: V2V
Depends On: 1621895
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-08-21 18:51 UTC by Nir Soffer
Modified: 2019-08-06 12:45 UTC (History)
7 users (show)

Fixed In Version: libguestfs-1.40.1-1.el7
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-08-06 12:44:27 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2019:2096 0 None None None 2019-08-06 12:45:45 UTC

Description Nir Soffer 2018-08-21 18:51:08 UTC 
Description of problem:

The oVirt server may fail a PUT request before reading all request body.
However before closing the connection, it writes a detailed error
response, that will make debugging issues like expired tickets much
easier to handle. If we don't get the response and log the error, the
error may be lost when the daemon log is rotated.

Current behavior is to log:
nbdkit: python[1]: error: /var/tmp/rhvupload.QAHE6K/rhv-upload-plugin.py: pwrite: error: [Errno 32] Broken pipe

oVirt server returns this error response in this case:
{
    "explanation": "Access was denied to this resource.",
    "code": 403,
    "detail": "Ticket u\'6071e16f-ec60-4ff9-a594-10b0faae3617\' expired",
    "title": "Forbidden"
}

If rhv-upload-plugin does not log the error, the error may be lost due to log
rotation of ovirt-imageio-dameon. See bug 1619019 for example case when we chased
this error for 2 weeks in the lab.

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

How reproducible:
Always

Steps to Reproduce:
It is hard to reproduce, see bug 1619019 for details.

Fix upstream by these patches:

commit 1368b1bb7d49c0d2a7ff0cc239559628d23c04d5
Author: Nir Soffer <nirsof>
Date:   Tue Aug 21 01:15:03 2018 +0300

    v2v: rhv-upload-plugin: Fix error formatting
    
    Fix the error format so we actually format the arguments instead of
    raising the format string and the arguments.
    
    Here is an upload error formatted correctly with this change:
    
    nbdkit: python[1]: error: /home/nsoffer/src/libguestfs/tmp/v2v.eC5yCl/rhv-upload-plugin.py:
    pwrite: error: could not write sector offset 218911744 size 3584: 403 Forbidden:
    b'{"explanation": "Access was denied to this resource.", "code": 403, "detail":
    "Ticket u\'61ac0483-48e3-4984-84d6-438884ba8bb2\' expired", "title": "Forbidden"}'

commit a651169085659259913d80ec84cd9bd7d832655a
Author: Nir Soffer <nirsof>
Date:   Tue Aug 21 01:15:02 2018 +0300

    v2v: rhv-upload-plugin: Handle send failures
    
    The oVirt server may fail a PUT request before reading all request body.
    However before closing the connection, it writes a detailed error
    response, that will make debugging issues like expired tickets much
    easier to handle. If we don't get the response and log the error, the
    error may be lost when the daemon log is rotated.
    
    Change pwrite() and emulate_zero() to get the response after EPIPE,
    failing with the error response from the oVirt server.
    
    Here is an example error log when a ticket expires during import:
    
    nbdkit: python[1]: error: /home/nsoffer/src/libguestfs/tmp/v2v.pRoyXm/rhv-upload-plugin.py:
    pwrite: error: ('%s: %d %s: %r', 'could not write sector offset 1841154048 size 1024', 403,
    'Forbidden', b'{"explanation": "Access was denied to this resource.", "code": 403, "detail":
    "Ticket u\'6071e16f-ec60-4ff9-a594-10b0faae3617\' expired", "title": "Forbidden"}')
Comment 2 Nir Soffer 2018-08-21 19:57:55 UTC 
How to reproduce:

The easiest way is to force a ticket to expire during virt-v2v import.

1. Start virt-v2v import, for example using local file

Best use mostly allocated image and slow storage, to increase the change the
ticket will expire during pwrite() request, and not during zero() request.

virt-v2v \
    -i disk /path/to/image \
    -o rhv-upload \
    -oc https://rhv-server/ovirt-engine/api \
    -os rhv-storage-domain-name \
    -op /var/tmp/password \
    -of raw \
    -oo rhv-cafile=ca.pem \
    -oo rhv-cluster=rhv-cluster-name \
    -oo rhv-direct=true

2. Wait until the transfer starts, and note the ticket value in ovirt-imageio-daemon log:

2018-08-21 03:31:03,747 INFO    (Thread-1) [tickets] [local] ADD ticket={u'url': u'file:///rhev/data-center/mnt/dumbo.tlv.redhat.com:_voodoo_v43-01/08272182-9fb1-4609-bd3b-0246b66eafa3/images/4820fe47-32aa-4b4e-8f98-04e7c0949819/8d0bb922-ee69-4fd0-a539-cc188af6749a', u'ops': [u'write'], u'uuid': u'0c51f337-aeb0-42c4-ac19-4d5aa507fb24', u'timeout': 300, u'size': 107374182400}

3. Make a the ticket expire in one second by sending this request:

(need to run as root)

curl --unix-socket /run/vdsm/ovirt-imageio-daemon.sock -X PATCH \
    -d '{"timeout": 1}' \
    http://localhost/tickets/'0c51f337-aeb0-42c4-ac19-4d5aa507fb24

The import should fail one second after this sending the request.

Expected results:
The error message should be something like:

nbdkit: python[1]: error: /var/tmp/rhvupload.QAHE6K/rhv-upload-plugin.py: pwrite: error: [Errno 32] Broken pipe

Note: the ticket may expire when sending zero request, but this does not reproduce
the issue, because zero() requests already display the error response from oVirt
server. If this happens, try again until you see: "pwrite: error:"


How to test the fix:

Repeat the same flow with the version including this fix.

The error message should show somehting like:

nbdkit: python[1]: error: /home/nsoffer/src/libguestfs/tmp/v2v.eC5yCl/rhv-upload-plugin.py:
pwrite: error: could not write sector offset 218911744 size 3584: 403 Forbidden:
b'{"explanation": "Access was denied to this resource.", "code": 403, "detail":
"Ticket u\'0c51f337-aeb0-42c4-ac19-4d5aa507fb24\' expired", "title": "Forbidden"}'
Comment 3 Nir Soffer 2018-08-21 20:00:04 UTC 
Correction: an unneeded quote character sneaked into the example command. Here is
correct example how to make a ticket expire:

curl --unix-socket /run/vdsm/ovirt-imageio-daemon.sock -X PATCH \
    -d '{"timeout": 1}' \
    http://localhost/tickets/0c51f337-aeb0-42c4-ac19-4d5aa507fb24
Comment 8 Pino Toscano 2019-01-17 11:40:41 UTC 
This bug will be fixed by the rebase scheduled for RHEL 7.7, see bug 1621895.
Comment 11 liuzi 2019-04-18 10:42:40 UTC 
Reproduce the bug with builds:
virt-v2v-1.38.2-12.el7.x86_64
libvirt-4.5.0-10.el7_6.4.x86_64
libguestfs-1.38.2-12.el7.x86_64
ovirt-imageio-common-1.4.6-1.el7ev.x86_64
ovirt-imageio-daemon-1.4.6-1.el7ev.noarch

Steps:
1.Use virt-v2v to convert a guest to rhv with rhv-upload option:
# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 esx6.7-rhel7.5-x86_64 --password-file /tmp/passwd -on rhel7.5-log -o rhv-upload -oc https://ibm-x3250m5-03.rhts.eng.pek2.redhat.com/ovirt-engine/api -os p2v_data -op /tmp/rhvpasswd -oo rhv-cafile=/home/ca.pem -oo rhv-direct=true -oo rhv-cluster=p2v

2.Wait until the transfer starts, and note the ticket value in ovirt-imageio-daemon log:

2019-04-18 18:16:03,126 INFO    (Thread-2529) [tickets] [local] ADD ticket={u'uuid': u'a99554d1-31d0-47da-9e89-53f8db3a33d4', u'ops': [u'write'], u'url': u'file:///rhev/data-center/mnt/10.73.224.199:_home_p2v__data/7b22dda5-0c99-4bdb-852b-c41332094b02/images/942104b6-fd0d-4dc5-b6e2-db34e6c50332/e92ad496-9936-4d33-8439-9b2624cdb799', u'sparse': True, u'timeout': 300, u'transfer_id': u'9661f1d4-06ce-4ee8-add3-757f5645b710', u'size': 12884901888}

3. Make the ticket expire in one second by sending this request:
#  curl --unix-socket /run/vdsm/ovirt-imageio-daemon.sock -X PATCH -d '{"timeout": 1}' http://localhost/tickets/a99554d1-31d0-47da-9e89-53f8db3a33d4

4.Check the error message:
# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 esx6.7-rhel7.5-x86_64 --password-file /tmp/passwd -on rhel7.5-log -o rhv-upload -oc https://ibm-x3250m5-03.rhts.eng.pek2.redhat.com/ovirt-engine/api -os p2v_data -op /tmp/rhvpasswd -oo rhv-cafile=/home/ca.pem -oo rhv-direct=true -oo rhv-cluster=p2v
[   0.3] Opening the source -i libvirt -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 esx6.7-rhel7.5-x86_64
[   2.5] Creating an overlay to protect the source from being modified
[   3.2] Initializing the target -o rhv-upload -oc https://ibm-x3250m5-03.rhts.eng.pek2.redhat.com/ovirt-engine/api -op /tmp/rhvpasswd -os p2v_data
[   4.6] Opening the overlay
[  26.3] Inspecting the overlay
[ 218.1] Checking for sufficient free disk space in the guest
[ 218.1] Estimating space required on target for each disk
[ 218.1] Converting Red Hat Enterprise Linux Server 7.5 (Maipo) to run on KVM
virt-v2v: This guest has virtio drivers installed.
[1405.0] Mapping filesystem data to avoid copying unused and blank areas
[1407.3] Closing the overlay
[1408.0] Checking if the guest needs BIOS or UEFI to boot
[1408.0] Assigning disks to buses
[1408.0] Copying disk 1/1 to qemu URI json:{ "file.driver": "nbd", "file.path": "/var/tmp/rhvupload.YZVNEV/nbdkit1.sock", "file.export": "/" } (raw)
nbdkit: python[1]: error: /var/tmp/rhvupload.YZVNEV/rhv-upload-plugin.py: pwrite: error: ['Traceback (most recent call last):\n', '  File "/var/tmp/rhvupload.YZVNEV/rhv-upload-plugin.py", line 383, in pwrite\n    http.send(buf)\n', '  File "/usr/lib64/python2.7/httplib.py", line 857, in send\n    self.sock.sendall(data)\n', '  File "/usr/lib64/python2.7/ssl.py", line 744, in sendall\n    v = self.send(data[count:])\n', '  File "/usr/lib64/python2.7/ssl.py", line 710, in send\n    v = self._sslobj.write(data)\n', 'error: [Errno 32] Broken pipe\n']
qemu-img: error while writing sector 11146624: Input/output error

nbdkit: python[1]: error: /var/tmp/rhvupload.YZVNEV/rhv-upload-plugin.py: flush: error: ['Traceback (most recent call last):\n', '  File "/var/tmp/rhvupload.YZVNEV/rhv-upload-plugin.py", line 484, in flush\n    http.request("PATCH", h[\'path\'], body=buf, headers=headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1041, in request\n    self._send_request(method, url, body, headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1069, in _send_request\n    self.putrequest(method, url, **skips)\n', '  File "/usr/lib64/python2.7/httplib.py", line 923, in putrequest\n    raise CannotSendRequest()\n', 'CannotSendRequest\n']
nbdkit: python[1]: error: /var/tmp/rhvupload.YZVNEV/rhv-upload-plugin.py: flush: error: ['Traceback (most recent call last):\n', '  File "/var/tmp/rhvupload.YZVNEV/rhv-upload-plugin.py", line 484, in flush\n    http.request("PATCH", h[\'path\'], body=buf, headers=headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1041, in request\n    self._send_request(method, url, body, headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1069, in _send_request\n    self.putrequest(method, url, **skips)\n', '  File "/usr/lib64/python2.7/httplib.py", line 923, in putrequest\n    raise CannotSendRequest()\n', 'CannotSendRequest\n']
virt-v2v: error: qemu-img command failed, see earlier errors

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]



Verify the bug with builds:
virt-v2v-1.40.2-3.el7.x86_64
libvirt-4.5.0-12.el7.x86_64
libguestfs-1.40.2-3.el7.x86_64
ovirt-imageio-common-1.4.6-1.el7ev.x86_64
ovirt-imageio-daemon-1.4.6-1.el7ev.noarch

Steps:
1.Use virt-v2v to convert a guest to rhv with rhv-upload option:
# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 esx6.7-rhel7.5-x86_64 --password-file /tmp/passwd -on rhel7.5-log -o rhv-upload -oc https://ibm-x3250m5-03.rhts.eng.pek2.redhat.com/ovirt-engine/api -os p2v_data -op /tmp/rhvpasswd -oo rhv-cafile=/home/ca.pem -oo rhv-direct=true -oo rhv-cluster=p2v

2.Wait until the transfer starts, and note the ticket value in ovirt-imageio-daemon log:

2019-04-18 17:35:16,049 INFO    (Thread-2239) [tickets] [local] ADD ticket={u'uuid': u'49f50a5b-e8b4-465b-a63c-aec476216c82', u'ops': [u'write'], u'url': u'file:///rhev/data-center/mnt/10.73.224.199:_home_p2v__data/7b22dda5-0c99-4bdb-852b-c41332094b02/images/151ed16b-56fd-44b8-96f5-acb7deb56426/50089966-4eea-43d5-8686-9141543f1d55', u'sparse': True, u'timeout': 300, u'transfer_id': u'd690fa40-322b-4d17-9838-0b340d665306', u'size': 12884901888}

3. Make the ticket expire in one second by sending this request:
#  curl --unix-socket /run/vdsm/ovirt-imageio-daemon.sock -X PATCH -d '{"timeout": 1}' http://localhost/tickets/49f50a5b-e8b4-465b-a63c-aec476216c82

4.Check the error message:
# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 esx6.7-rhel7.5-x86_64 --password-file /tmp/passwd -on rhel7.5-log -o rhv-upload -oc https://ibm-x3250m5-03.rhts.eng.pek2.redhat.com/ovirt-engine/api -os p2v_data -op /tmp/rhvpasswd -oo rhv-cafile=/home/ca.pem -oo rhv-direct=true -oo rhv-cluster=p2v
[   0.3] Opening the source -i libvirt -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 esx6.7-rhel7.5-x86_64
[   2.2] Creating an overlay to protect the source from being modified
[   3.1] Opening the overlay
[  22.7] Inspecting the overlay
[ 199.2] Checking for sufficient free disk space in the guest
[ 199.2] Estimating space required on target for each disk
[ 199.2] Converting Red Hat Enterprise Linux Server 7.5 (Maipo) to run on KVM
virt-v2v: This guest has virtio drivers installed.
[1467.5] Mapping filesystem data to avoid copying unused and blank areas
[1468.9] Closing the overlay
[1469.0] Assigning disks to buses
[1469.0] Checking if the guest needs BIOS or UEFI to boot
[1469.0] Initializing the target -o rhv-upload -oc https://ibm-x3250m5-03.rhts.eng.pek2.redhat.com/ovirt-engine/api -op /tmp/rhvpasswd -os p2v_data
[1471.8] Copying disk 1/1 to qemu URI json:{ "file.driver": "nbd", "file.path": "/var/tmp/rhvupload.KxcNAI/nbdkit0.sock", "file.export": "/" } (raw)
nbdkit: python[1]: error: /var/tmp/v2v.8ma9XT/rhv-upload-plugin.py: pwrite: error: ['Traceback (most recent call last):\n', '  File "/var/tmp/v2v.8ma9XT/rhv-upload-plugin.py", line 405, in pwrite\n    (offset, count))\n', '  File "/var/tmp/v2v.8ma9XT/rhv-upload-plugin.py", line 354, in request_failed\n    raise RuntimeError("%s: %d %s: %r" % (msg, status, reason, body[:200]))\n', 'RuntimeError: could not write sector offset 2363490304 size 16384: 403 Forbidden: \'{"explanation": "Access was denied to this resource.", "code": 403, "detail": "Ticket u\\\'49f50a5b-e8b4-465b-a63c-aec476216c82\\\' expired", "title": "Forbidden"}\'\n']
qemu-img: error while writing sector 4616192: Input/output error

nbdkit: python[1]: error: /var/tmp/v2v.8ma9XT/rhv-upload-plugin.py: flush: error: ['Traceback (most recent call last):\n', '  File "/var/tmp/v2v.8ma9XT/rhv-upload-plugin.py", line 503, in flush\n    http.request("PATCH", h[\'path\'], body=buf, headers=headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1041, in request\n    self._send_request(method, url, body, headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1075, in _send_request\n    self.endheaders(body)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1037, in endheaders\n    self._send_output(message_body)\n', '  File "/usr/lib64/python2.7/httplib.py", line 881, in _send_output\n    self.send(msg)\n', '  File "/usr/lib64/python2.7/httplib.py", line 857, in send\n    self.sock.sendall(data)\n', '  File "/usr/lib64/python2.7/ssl.py", line 744, in sendall\n    v = self.send(data[count:])\n', '  File "/usr/lib64/python2.7/ssl.py", line 710, in send\n    v = self._sslobj.write(data)\n', 'error: [Errno 32] Broken pipe\n']
nbdkit: python[1]: error: /var/tmp/v2v.8ma9XT/rhv-upload-plugin.py: flush: error: ['Traceback (most recent call last):\n', '  File "/var/tmp/v2v.8ma9XT/rhv-upload-plugin.py", line 503, in flush\n    http.request("PATCH", h[\'path\'], body=buf, headers=headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1041, in request\n    self._send_request(method, url, body, headers)\n', '  File "/usr/lib64/python2.7/httplib.py", line 1069, in _send_request\n    self.putrequest(method, url, **skips)\n', '  File "/usr/lib64/python2.7/httplib.py", line 923, in putrequest\n    raise CannotSendRequest()\n', 'CannotSendRequest\n']
virt-v2v: error: qemu-img command failed, see earlier errors

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

Result:
The log's format is correct when a ticket expires during import guest,so change the bug from ON_QA to VERIFIED.
Comment 12 Xiaodai Wang 2019-07-01 03:57:56 UTC 
It seems like 'BrokenPipeError' does not work in python2? I tested it with virt-v2v-1.40.2-5.el7.x86_64 which has 8f250c00c8b028a614815f63b2713748504d7ef9.

nbdkit: python[1]: error: /var/tmp/v2v.4MjouT/rhv-upload-plugin.py: pwrite: error: ['Traceback (most recent call last):\n', '  File "/var/tmp/v2v.4MjouT/rhv-upload-plugin.py", line 398, in pwrite\n    except BrokenPipeError:\n', "NameError: global name 'BrokenPipeError' is not defined\n"]
Comment 13 Xiaodai Wang 2019-07-02 09:34:08 UTC 
(In reply to Xiaodai Wang from comment #12)
> It seems like 'BrokenPipeError' does not work in python2? I tested it with
> virt-v2v-1.40.2-5.el7.x86_64 which has
> 8f250c00c8b028a614815f63b2713748504d7ef9.
> 
> nbdkit: python[1]: error: /var/tmp/v2v.4MjouT/rhv-upload-plugin.py: pwrite:
> error: ['Traceback (most recent call last):\n', '  File
> "/var/tmp/v2v.4MjouT/rhv-upload-plugin.py", line 398, in pwrite\n    except
> BrokenPipeError:\n', "NameError: global name 'BrokenPipeError' is not
> defined\n"]

Filed a new bug for this problem.
Bug 1726168 - NameError: global name 'BrokenPipeError' is not defined
Comment 15 errata-xmlrpc 2019-08-06 12:44:27 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

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

https://access.redhat.com/errata/RHEA-2019:2096
Note You need to log in before you can comment on or make changes to this bug.