[PATCH] v2v: Log full imageio response on failure.
Thanks: Nir Soffer --- v2v/rhv-upload-plugin.py | 66 ++++++++++++++++++++++++++++-------------------- 1 file changed, 39 insertions(+), 27 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 791c9e7d2..c3de7d555 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -228,6 +228,29 @@ def can_flush(h): def get_size(h): return params['disk_size'] +# Any unexpected HTTP response status from the server will end up +# calling this function which logs the full error, pauses the +# transfer, sets the failed state, and raises a RuntimeError +# exception. +def unexpected_response(h, r, msg): + # Setting the failed flag in the handle causes the disk to be + # cleaned up on close. + h['failed'] = True + h['transfer_service'].pause() + + status = r.status + reason = r.reason + body = r.read() + + # Log the full error if we're verbose. + debug("unexpected response from imageio server:") + debug(msg) + debug("%d: %s" % (status, reason)) + debug(body) + + # Only a short error is included in the exception. + raise RuntimeError("%s: %d: %s" % (msg, status, reason)) + # For documentation see: # https://github.com/oVirt/ovirt-imageio/blob/master/docs/random-io.md # For examples of working code to read/write from the server, see: @@ -248,16 +271,14 @@ def pread(h, count, offset): r = http.getresponse() # 206 = HTTP Partial Content. if r.status != 206: - h['transfer_service'].pause() - h['failed'] = True - raise RuntimeError("could not read sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not read sector offset %d size %d" % + (offset, count)) return r.read() def pwrite(h, buf, offset): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service'] count = len(buf) h['highestwrite'] = max(h['highestwrite'], offset+count) @@ -275,15 +296,13 @@ def pwrite(h, buf, offset): r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not write sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not write sector offset %d size %d" % + (offset, count)) def zero(h, count, offset, may_trim): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service'] # Unlike the trim and flush calls, there is no 'can_zero' method # so nbdkit could call this even if the server doesn't support @@ -306,10 +325,9 @@ def zero(h, count, offset, may_trim): r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not zero sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not zero sector offset %d size %d" % + (offset, count)) def emulate_zero(h, count, offset): # qemu-img convert starts by trying to zero/trim the whole device. @@ -334,15 +352,13 @@ def emulate_zero(h, count, offset): r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not write zeroes (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not write zeroes offset %d size %d" % + (offset, count)) def trim(h, count, offset): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service'] # Construct the JSON request for trimming. buf = json.dumps({'op': "trim", @@ -358,15 +374,13 @@ def trim(h, count, offset): r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not trim sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not trim sector offset %d size %d" % + (offset, count)) def flush(h): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service'] # Construct the JSON request for flushing. buf = json.dumps({'op': "flush"}).encode() @@ -379,9 +393,7 @@ def flush(h): r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not flush: %d: %s" % (r.status, r.reason)) + unexpected_response(h, r, "could not flush") def delete_disk_on_failure(h): disk_service = h['disk_service'] -- 2.16.2
On Tue, Jun 5, 2018 at 4:40 PM Richard W.M. Jones <rjones@redhat.com> wrote:
Thanks: Nir Soffer --- v2v/rhv-upload-plugin.py | 66 ++++++++++++++++++++++++++++-------------------- 1 file changed, 39 insertions(+), 27 deletions(-)
diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 791c9e7d2..c3de7d555 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -228,6 +228,29 @@ def can_flush(h): def get_size(h): return params['disk_size']
+# Any unexpected HTTP response status from the server will end up +# calling this function which logs the full error, pauses the +# transfer, sets the failed state, and raises a RuntimeError +# exception. +def unexpected_response(h, r, msg):
This is not really unexpected response, maybe "request_failed"?
+ # Setting the failed flag in the handle causes the disk to be + # cleaned up on close. + h['failed'] = True + h['transfer_service'].pause() + + status = r.status + reason = r.reason + body = r.read()
This should not fail, but if we there is a possible failure, it would be more robust to do: try: body = r.read() except EnvironmentError as e: body = "(Unable to read response body: %s)" % e If this raises as is, we would fail with EnvironmentError, hiding the status, reason, and msg.
+ + # Log the full error if we're verbose. + debug("unexpected response from imageio server:") + debug(msg) + debug("%d: %s" % (status, reason)) + debug(body)
Hiding fatal error in non-verbose will make it hard to support.
+ + # Only a short error is included in the exception. + raise RuntimeError("%s: %d: %s" % (msg, status, reason))
And instead include the start of the body in the error text like this: raise RuntimeError("%s: [%d] %s: %r", msg, status, reason, bofy[:200]) (Using %r to avoid unwanted newlines in the response).
+ # For documentation see: # https://github.com/oVirt/ovirt-imageio/blob/master/docs/random-io.md # For examples of working code to read/write from the server, see: @@ -248,16 +271,14 @@ def pread(h, count, offset): r = http.getresponse() # 206 = HTTP Partial Content. if r.status != 206: - h['transfer_service'].pause() - h['failed'] = True - raise RuntimeError("could not read sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not read sector offset %d size %d" % + (offset, count))
This is much nicer.
return r.read()
def pwrite(h, buf, offset): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service']
count = len(buf) h['highestwrite'] = max(h['highestwrite'], offset+count) @@ -275,15 +296,13 @@ def pwrite(h, buf, offset):
r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not write sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not write sector offset %d size %d" % + (offset, count))
def zero(h, count, offset, may_trim): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service']
# Unlike the trim and flush calls, there is no 'can_zero' method # so nbdkit could call this even if the server doesn't support @@ -306,10 +325,9 @@ def zero(h, count, offset, may_trim):
r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not zero sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not zero sector offset %d size %d" % + (offset, count))
def emulate_zero(h, count, offset): # qemu-img convert starts by trying to zero/trim the whole device. @@ -334,15 +352,13 @@ def emulate_zero(h, count, offset):
r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not write zeroes (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not write zeroes offset %d size %d" % + (offset, count))
def trim(h, count, offset): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service']
# Construct the JSON request for trimming. buf = json.dumps({'op': "trim", @@ -358,15 +374,13 @@ def trim(h, count, offset):
r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not trim sector (%d, %d): %d: %s" % - (offset, count, r.status, r.reason)) + unexpected_response(h, r, + "could not trim sector offset %d size %d" % + (offset, count))
def flush(h): http = h['http'] transfer = h['transfer'] - transfer_service = h['transfer_service']
# Construct the JSON request for flushing. buf = json.dumps({'op': "flush"}).encode() @@ -379,9 +393,7 @@ def flush(h):
r = http.getresponse() if r.status != 200: - transfer_service.pause() - h['failed'] = True - raise RuntimeError("could not flush: %d: %s" % (r.status, r.reason)) + unexpected_response(h, r, "could not flush")
def delete_disk_on_failure(h): disk_service = h['disk_service']
Nir
On Tue, Jun 05, 2018 at 09:35:34PM +0300, Nir Soffer wrote:
+ # Log the full error if we're verbose. + debug("unexpected response from imageio server:") + debug(msg) + debug("%d: %s" % (status, reason)) + debug(body)
Hiding fatal error in non-verbose will make it hard to support.
A quick note that we're always in debug mode when run under oVirt. I'll fix the rest of the stuff and post an updated patch. Thanks for the comprehensive review, 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
participants (2)
-
Nir Soffer -
Richard W.M. Jones