[PATCH 0/2] v2v: rhv-upload-plugin: Improve error handling
These patches improve error handling when PUT request fail, including the error response from oVirt server. This will make it easier to debug issue when oVirt server logs have been rotated. Nir Soffer (2): v2v: rhv-upload-plugin: Handle send send failures v2v: rhv-upload-plugin: Fix error formatting v2v/rhv-upload-plugin.py | 24 +++++++++++++++++------- 1 file changed, 17 insertions(+), 7 deletions(-) -- 2.17.1
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"}') --- v2v/rhv-upload-plugin.py | 22 ++++++++++++++++------ 1 file changed, 16 insertions(+), 6 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 2d686c2da..7327ea4c5 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -17,6 +17,7 @@ # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. import builtins +import errno import json import logging import socket @@ -357,7 +358,12 @@ def pwrite(h, buf, offset): http.putheader("Content-Range", "bytes %d-%d/*" % (offset, offset+count-1)) http.putheader("Content-Length", str(count)) http.endheaders() - http.send(buf) + + try: + http.send(buf) + except socket.error as e: + if e[0] != errno.EPIPE: + raise r = http.getresponse() if r.status != 200: @@ -413,11 +419,15 @@ def emulate_zero(h, count, offset): http.putheader("Content-Length", str(count)) http.endheaders() - buf = bytearray(128*1024) - while count > len(buf): - http.send(buf) - count -= len(buf) - http.send(buffer(buf, 0, count)) + try: + buf = bytearray(128*1024) + while count > len(buf): + http.send(buf) + count -= len(buf) + http.send(buffer(buf, 0, count)) + except socket.error as e: + if e[0] != errno.EPIPE: + raise r = http.getresponse() if r.status != 200: -- 2.17.1
On Tue, Aug 21, 2018 at 01:15:02AM +0300, Nir Soffer wrote:
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.
This series looks fine, I'll push it in a minute. Couple of questions: (1) Are we using the nbdkit enhanced Python error reporting yet? What's stopping us if we are not? (2) Is there a BZ associated with this change? If not, we'll need one if you want to get these changes into RHEL. Thanks, Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com Fedora Windows cross-compiler. Compile Windows programs, test, and build Windows installers. Over 100 libraries supported. http://fedoraproject.org/wiki/MinGW
On Tue, Aug 21, 2018 at 2:02 PM Richard W.M. Jones <rjones@redhat.com> wrote:
On Tue, Aug 21, 2018 at 01:15:02AM +0300, Nir Soffer wrote:
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.
This series looks fine, I'll push it in a minute.
Couple of questions:
(1) Are we using the nbdkit enhanced Python error reporting yet? What's stopping us if we are not?
In request_failed() we raise RuntimeError, so it should log a traceback, but I did not see a traceback, maybe because I did not test it in verbose mode. (2) Is there a BZ associated with this change? If not, we'll need one
if you want to get these changes into RHEL.
Not yet, the only thing we have is https://bugzilla.redhat.com/1619019, showing why this change is important. I will open a new bug for this. Nir
On Tue, Aug 21, 2018 at 02:40:49PM +0300, Nir Soffer wrote:
On Tue, Aug 21, 2018 at 2:02 PM Richard W.M. Jones <rjones@redhat.com> wrote:
On Tue, Aug 21, 2018 at 01:15:02AM +0300, Nir Soffer wrote:
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.
This series looks fine, I'll push it in a minute.
Couple of questions:
(1) Are we using the nbdkit enhanced Python error reporting yet? What's stopping us if we are not?
In request_failed() we raise RuntimeError, so it should log a traceback, but I did not see a traceback, maybe because I did not test it in verbose mode.
If you see anything at all, then you'd see the traceback. It seems more likely that whatever version of nbdkit being used does not include: https://github.com/libguestfs/nbdkit/commit/72c0d64a47db642cafa89884f2ee554b... This has now been backported to the 1.2 & 1.4 branches as well. Do you know what version (of nbdkit) they are testing with? Thanks for opening the bug, let me know the BZ# when you have it. Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com libguestfs lets you edit virtual machines. Supports shell scripting, bindings from many languages. http://libguestfs.org
On Tue, Aug 21, 2018 at 2:49 PM Richard W.M. Jones <rjones@redhat.com> wrote:
On Tue, Aug 21, 2018 at 2:02 PM Richard W.M. Jones <rjones@redhat.com> wrote:
On Tue, Aug 21, 2018 at 01:15:02AM +0300, Nir Soffer wrote:
The oVirt server may fail a PUT request before reading all request
On Tue, Aug 21, 2018 at 02:40:49PM +0300, Nir Soffer wrote: 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.
This series looks fine, I'll push it in a minute.
Couple of questions:
(1) Are we using the nbdkit enhanced Python error reporting yet? What's stopping us if we are not?
In request_failed() we raise RuntimeError, so it should log a traceback, but I did not see a traceback, maybe because I did not test it in verbose mode.
If you see anything at all, then you'd see the traceback.
It seems more likely that whatever version of nbdkit being used does not include:
https://github.com/libguestfs/nbdkit/commit/72c0d64a47db642cafa89884f2ee554b...
This has now been backported to the 1.2 & 1.4 branches as well. Do you know what version (of nbdkit) they are testing with?
Tested with: $ rpm -qa | grep nbdkit nbdkit-plugin-python3-1.4.2-1.fc28.x86_64 nbdkit-1.4.2-1.fc28.x86_64 nbdkit-plugin-python-common-1.4.2-1.fc28.x86_64
Thanks for opening the bug, let me know the BZ# when you have it.
Rich.
-- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com libguestfs lets you edit virtual machines. Supports shell scripting, bindings from many languages. http://libguestfs.org
On Tue, Aug 21, 2018 at 03:55:50PM +0300, Nir Soffer wrote:
On Tue, Aug 21, 2018 at 2:49 PM Richard W.M. Jones <rjones@redhat.com> wrote:
It seems more likely that whatever version of nbdkit being used does not include:
https://github.com/libguestfs/nbdkit/commit/72c0d64a47db642cafa89884f2ee554b...
This has now been backported to the 1.2 & 1.4 branches as well. Do you know what version (of nbdkit) they are testing with?
Tested with: $ rpm -qa | grep nbdkit nbdkit-plugin-python3-1.4.2-1.fc28.x86_64 nbdkit-1.4.2-1.fc28.x86_64 nbdkit-plugin-python-common-1.4.2-1.fc28.x86_64
I think if you upgrade to 1.4.3 (which is still in testing in Fedora) you should get full tracebacks. https://bodhi.fedoraproject.org/updates/FEDORA-2018-92ee422873 (see "python" here: https://github.com/libguestfs/nbdkit/commits/stable-1.4 ) Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-builder quickly builds VMs from scratch http://libguestfs.org/virt-builder.1.html
On Tue, Aug 21, 2018 at 4:03 PM Richard W.M. Jones <rjones@redhat.com> wrote:
On Tue, Aug 21, 2018 at 03:55:50PM +0300, Nir Soffer wrote:
On Tue, Aug 21, 2018 at 2:49 PM Richard W.M. Jones <rjones@redhat.com> wrote:
It seems more likely that whatever version of nbdkit being used does not include:
https://github.com/libguestfs/nbdkit/commit/72c0d64a47db642cafa89884f2ee554b...
This has now been backported to the 1.2 & 1.4 branches as well. Do you know what version (of nbdkit) they are testing with?
Tested with: $ rpm -qa | grep nbdkit nbdkit-plugin-python3-1.4.2-1.fc28.x86_64 nbdkit-1.4.2-1.fc28.x86_64 nbdkit-plugin-python-common-1.4.2-1.fc28.x86_64
I think if you upgrade to 1.4.3 (which is still in testing in Fedora) you should get full tracebacks.
https://bodhi.fedoraproject.org/updates/FEDORA-2018-92ee422873 (see "python" here: https://github.com/libguestfs/nbdkit/commits/stable-1.4 )
After upgrading from update-testing repo: $ rpm -qa | grep nbdkit nbdkit-plugin-python3-1.4.3-1.fc28.x86_64 nbdkit-plugin-python-common-1.4.3-1.fc28.x86_64 nbdkit-1.4.3-1.fc28.x86_64 Here is output when simulating expired ticket in verbose mode. unexpected response from imageio server: could not write sector offset 1897857024 size 65536 403: Forbidden b'{"explanation": "Access was denied to this resource.", "code": 403, "detail": "Ticket u\'acdad591-f29e-4d85-bf41-046e250aa015\' expired", "title": "Forbidden"}' nbdkit: python[1]: error: /home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py: pwrite: error: ['Traceback (most recent call last):\n', ' File "/home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py", line 373, in pwrite\n (offset, count))\n', ' File "/home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py", line 321, in request_failed\n raise RuntimeError("%s: %d %s: %r" % (msg, status, reason, body[:200]))\n', 'RuntimeError: could not write sector offset 1897857024 size 65536: 403 Forbidden: b\'{"explanation": "Access was denied to this resource.", "code": 403, "detail": "Ticket u\\\'acdad591-f29e-4d85-bf41-046e250aa015\\\' expired", "title": "Forbidden"}\'\n'] nbdkit: python[1]: debug: sending error reply: Input/output error qemu-img: error while writing sector 3706752: Input/output error Nir
On Tue, Aug 21, 2018 at 10:47:01PM +0300, Nir Soffer wrote:
Here is output when simulating expired ticket in verbose mode.
unexpected response from imageio server: could not write sector offset 1897857024 size 65536 403: Forbidden b'{"explanation": "Access was denied to this resource.", "code": 403, "detail": "Ticket u\'acdad591-f29e-4d85-bf41-046e250aa015\' expired", "title": "Forbidden"}' nbdkit: python[1]: error: /home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py: pwrite: error: ['Traceback (most recent call last):\n', ' File "/home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py", line 373, in pwrite\n (offset, count))\n', ' File "/home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py", line 321, in request_failed\n raise RuntimeError("%s: %d %s: %r" % (msg, status, reason, body[:200]))\n', 'RuntimeError: could not write sector offset 1897857024 size 65536: 403 Forbidden: b\'{"explanation": "Access was denied to this resource.", "code": 403, "detail": "Ticket u\\\'acdad591-f29e-4d85-bf41-046e250aa015\\\' expired", "title": "Forbidden"}\'\n'] nbdkit: python[1]: debug: sending error reply: Input/output error qemu-img: error while writing sector 3706752: Input/output error
Given the limitation of having to have a single line output in the error message, this seems like it's doing the right thing to me. You can (painfully) rewrite the error message to make it look like the original: Traceback (most recent call last): File "/home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py", line 373, in pwrite (offset, count)) File "/home/nsoffer/src/libguestfs/tmp/v2v.ayEM8r/rhv-upload-plugin.py", line 321, in request_failed raise RuntimeError("%s: %d %s: %r" % (msg, status, reason, body[:200])) RuntimeError: could not write sector offset 1897857024 size 65536: 403 Forbidden: b{"explanation": "Access was denied to this resource.", "code": 403, "detail": "Ticket u'acdad591-f29e-4d85-bf41-046e250aa015' expired", "title": "Forbidden"} So it looks like all the information is still there, particularly about the expired ticket. Thanks for testing this, Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com Fedora Windows cross-compiler. Compile Windows programs, test, and build Windows installers. Over 100 libraries supported. http://fedoraproject.org/wiki/MinGW
On Tue, Aug 21, 2018 at 2:49 PM Richard W.M. Jones <rjones@redhat.com> wrote:
Thanks for opening the bug, let me know the BZ# when you have it.
https://bugzilla.redhat.com/1619805 I'll instructions how to test this later. Nir
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"}' --- v2v/rhv-upload-plugin.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 7327ea4c5..b5dd5521d 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -317,7 +317,7 @@ def request_failed(h, r, msg): debug(body) # Only a short error is included in the exception. - raise RuntimeError("%s: %d %s: %r", msg, status, reason, body[:200]) + raise RuntimeError("%s: %d %s: %r" % (msg, status, reason, body[:200])) # For documentation see: # https://github.com/oVirt/ovirt-imageio/blob/master/docs/random-io.md -- 2.17.1
participants (3)
-
Nir Soffer -
Nir Soffer -
Richard W.M. Jones