Libguestfs - Mar 2019 - [PATCH v3] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)

On Sun, Mar 17, 2019 at 3:51 PM Daniel Erez <derez@redhat.com> wrote:
> After invoking transfer_service.finalize, check operation
> status by examining DiskStatus.
> This is done instead of failing after a predefined timeout
> regardless the status.
>
> * not verified *
>
> Bug-Url: https://bugzilla.redhat.com/show_bug.cgi?id=1680361
> ---
>  v2v/rhv-upload-plugin.py | 18 +++++++++++++-----
>  1 file changed, 13 insertions(+), 5 deletions(-)
>
> diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py
> index 2a950c5ed..6f65e034b 100644
> --- a/v2v/rhv-upload-plugin.py
> +++ b/v2v/rhv-upload-plugin.py
> @@ -523,15 +523,23 @@ def close(h):
>          # waiting for the transfer object to cease to exist, which
>          # falls through to the exception case and then we can
>          # continue.
> -        endt = time.time() + timeout
> +        disk_id = disk.id
> +        start = time.time()
>          try:
>              while True:
>                  time.sleep(1)
> -                tmp = transfer_service.get()
> -                if time.time() > endt:
> -                    raise RuntimeError("timed out waiting for
transfer "
> -                                       "to finalize")
> +                disk_service = h['disk_service']
>
We can clean this a little bit by doing this outside of the loop.

> +                disk = disk_service.get()
> +                if disk.status == types.DiskStatus.LOCKED:
> +                    if time.time() > start + timeout:
> +                        raise RuntimeError("timed out waiting for
> transfer "
> +                                           "to finalize")
> +                    continue
> +                if disk.status == types.DiskStatus.OK:
> +                    debug("finalized after %s seconds",
time.time() -
> start)
> +                    break
>          except sdk.NotFoundError:
> +            debug("transfer finalize failed for disk: %s",
disk_id)
>
This should explain the failure:

    "transfer failed: disk %s not found"

>              pass
>
This should be a failure now.

>
>          # Write the disk ID file.  Only do this on successful completion.
> --
>
Waiting only for the disk is much nicer.

Nir

After invoking transfer_service.finalize, check operation
status by examining DiskStatus.
This is done instead of failing after a predefined timeout
regardless the status.

* not verified *

Bug-Url: https://bugzilla.redhat.com/show_bug.cgi?id=1680361
---
 v2v/rhv-upload-plugin.py | 19 +++++++++++++------
 1 file changed, 13 insertions(+), 6 deletions(-)

diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py
index 2a950c5ed..2cefe94b0 100644
--- a/v2v/rhv-upload-plugin.py
+++ b/v2v/rhv-upload-plugin.py
@@ -523,16 +523,23 @@ def close(h):
         # waiting for the transfer object to cease to exist, which
         # falls through to the exception case and then we can
         # continue.
-        endt = time.time() + timeout
+        disk_id = disk.id
+        start = time.time()
         try:
             while True:
                 time.sleep(1)
-                tmp = transfer_service.get()
-                if time.time() > endt:
-                    raise RuntimeError("timed out waiting for transfer
"
-                                       "to finalize")
+                disk_service = h['disk_service']
+                disk = disk_service.get()
+                if disk.status == types.DiskStatus.LOCKED:
+                    if time.time() > start + timeout:
+                        raise RuntimeError("timed out waiting for transfer
"
+                                           "to finalize")
+                    continue
+                if disk.status == types.DiskStatus.OK:
+                    debug("finalized after %s seconds", time.time() -
start)
+                    break
         except sdk.NotFoundError:
-            pass
+            raise RuntimeError("transfer failed: disk %s not found" %
disk_id)

         # Write the disk ID file.  Only do this on successful completion.
         with builtins.open(params['diskid_file'], 'w') as fp:
--

On Mon, Mar 18, 2019 at 06:51:26PM +0200, Daniel Erez
wrote:
> After invoking transfer_service.finalize, check operation
> status by examining DiskStatus.
> This is done instead of failing after a predefined timeout
> regardless the status.
> 
> * not verified *
> 
> Bug-Url: https://bugzilla.redhat.com/show_bug.cgi?id=1680361
> ---
>  v2v/rhv-upload-plugin.py | 19 +++++++++++++------
>  1 file changed, 13 insertions(+), 6 deletions(-)
> 
> diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py
> index 2a950c5ed..2cefe94b0 100644
> --- a/v2v/rhv-upload-plugin.py
> +++ b/v2v/rhv-upload-plugin.py
> @@ -523,16 +523,23 @@ def close(h):
>          # waiting for the transfer object to cease to exist, which
>          # falls through to the exception case and then we can
>          # continue.
> -        endt = time.time() + timeout
> +        disk_id = disk.id
> +        start = time.time()
>          try:
>              while True:
>                  time.sleep(1)
> -                tmp = transfer_service.get()
> -                if time.time() > endt:
> -                    raise RuntimeError("timed out waiting for
transfer "
> -                                       "to finalize")
> +                disk_service = h['disk_service']
> +                disk = disk_service.get()
> +                if disk.status == types.DiskStatus.LOCKED:
> +                    if time.time() > start + timeout:
> +                        raise RuntimeError("timed out waiting for
transfer "
> +                                           "to finalize")
> +                    continue
> +                if disk.status == types.DiskStatus.OK:
> +                    debug("finalized after %s seconds",
time.time() - start)
> +                    break
>          except sdk.NotFoundError:
> -            pass
> +            raise RuntimeError("transfer failed: disk %s not
found" % disk_id)
> 
>          # Write the disk ID file.  Only do this on successful completion.
>          with builtins.open(params['diskid_file'], 'w') as
fp:
Ilanit tested this patch for us.  Unfortunately it fails for reasons I
don't really understand but seem to be deep inside the RHV API:

nbdkit: python[1]: error: /var/tmp/v2v.sZm0my/rhv-upload-plugin.py: close:
error: ['Traceback (most recent call last):
', '  File "/var/tmp/v2v.sZm0my/rhv-upload-plugin.py", line
577, in close
', '  File "/var/tmp/v2v.sZm0my/rhv-upload-plugin.py", line
516, in delete_disk_on_failure
', '  File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/services.py", line
37334, in remove
    self._internal_remove(headers, query, wait)
', '  File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 271,
in _internal_remove
    return future.wait() if wait else future
', '  File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 55, in
wait
    return self._code(response)
', '  File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 268,
in callback
    self._check_fault(response)
', '  File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 132,
in _check_fault
    self._raise_error(response, body)
', '  File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 118,
in _raise_error
    raise error
', 'Error: Fault reason is "Operation Failed". Fault detail is
"[Cannot remove Virtual Disk. Related operation is currently in progress.
Please try again later.]". HTTP response code is 409.
']

Can you help us to understand what we need to do to fix this?

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-top is 'top' for virtual machines.  Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://people.redhat.com/~rjones/virt-top