Libguestfs - Jun 2018 - [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