Bug 1619805
| Summary: | Log error response from oVirt server in rhv-upload-plugin | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | Nir Soffer <nsoffer> |
| Component: | libguestfs | Assignee: | Richard W.M. Jones <rjones> |
| Status: | CLOSED ERRATA | QA Contact: | Virtualization Bugs <virt-bugs> |
| Severity: | high | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 7.6 | CC: | juzhou, mxie, mzhan, ptoscano, tzheng, xiaodwan, zili |
| Target Milestone: | rc | ||
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | V2V | ||
| Fixed In Version: | libguestfs-1.40.1-1.el7 | Doc Type: | If docs needed, set a value |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2019-08-06 12:44:27 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
| Bug Depends On: | 1621895 | ||
| Bug Blocks: | |||
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"}'
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
This bug will be fixed by the rebase scheduled for RHEL 7.7, see bug 1621895. 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. 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"] (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 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 |
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"}')