7:07 a.m.
After invoking transfer_service.finalize, check operation
status by examining ImageTransferPhase and 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 | 26 +++++++++++++++++++++-----
1 file changed, 21 insertions(+), 5 deletions(-)
diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py
index 2a950c5ed..873c11ce1 100644
--- a/v2v/rhv-upload-plugin.py
+++ b/v2v/rhv-upload-plugin.py
@@ -523,14 +523,30 @@ 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
+ 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")
+ transfer = transfer_service.get()
+
+ if transfer is None:
+ disk_service = h['disk_service']
+ disk = disk_service.get()
+ if disk.status == types.DiskStatus.OK:
+ continue
+
+ if transfer.phase == types.ImageTransferPhase.FINISHED_SUCCESS:
+ debug("finalized after %s seconds", time.time() - start)
+ break
+
+ if transfer.phase ==
types.ImageTransferPhase.FINALIZING_SUCCESS:
+ if time.time() > start + timeout:
+ raise RuntimeError("timed out waiting for transfer "
+ "to finalize")
+ continue
+
+ raise RuntimeError("Unexpected transfer phase while
finalizing "
+ "upload %r" % transfer.phase)
except sdk.NotFoundError:
pass
--
7:59 a.m.
On Sun, Mar 17, 2019 at 2:07 PM Daniel Erez <derez(a)redhat.com> wrote:
After invoking transfer_service.finalize, check operation
status by examining ImageTransferPhase and 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 | 26 +++++++++++++++++++++-----
1 file changed, 21 insertions(+), 5 deletions(-)
diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py
index 2a950c5ed..873c11ce1 100644
--- a/v2v/rhv-upload-plugin.py
+++ b/v2v/rhv-upload-plugin.py
@@ -523,14 +523,30 @@ 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
+ 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")
+ transfer = transfer_service.get()
+
+ if transfer is None:
Are you sure this is possible? the original code assumed that we
fail with sdk.NotFoundError.
+ disk_service = h['disk_service']
+ disk = disk_service.get()
+ if disk.status == types.DiskStatus.OK:
+ continue
If the disk status is OK the upload was finished, so we should break, no?
If the disk status is LOCKED, we should continue. But in this case there is
no point to check the transfer again.
What if the finalize failed, and the disk was deleted? Do we get disk = None
or some exception?
+
+ if transfer.phase ==
types.ImageTransferPhase.FINISHED_SUCCESS:
+ debug("finalized after %s seconds", time.time() -
start)
+ break
+
+ if transfer.phase ==
types.ImageTransferPhase.FINALIZING_SUCCESS:
+ if time.time() > start + timeout:
+ raise RuntimeError("timed out waiting for
transfer "
+ "to finalize")
+ continue
+
+ raise RuntimeError("Unexpected transfer phase while
finalizing "
+ "upload %r" % transfer.phase)
except sdk.NotFoundError:
pass
Is this error possible? We need to add debug log here.
I think the logic should be:
while True:
wait
get transfer
if transfer does not exists (None or sdk.NotFoundErro) , break
if transfer is finished, break (success)
if transfer is finalizing:
if timed out, fail
continue
fail with invalid transfer phase
while True:
wait
get disk
if disk does not exists (None or sdk.NotFoundErro), fail
if disk is OK, break (success)
if disk is locked:
if timed out, fail
continue
fail with invalid disk status
This is little bit crazy that all user have to do this.
We need to change engine so transfer is kept in the database after it
finished for enough
time (1 hour?), so user can wait *only* for the transfer.
Nir
8:47 a.m.
On Sun, Mar 17, 2019 at 2:59 PM Nir Soffer <nsoffer(a)redhat.com> wrote:
On Sun, Mar 17, 2019 at 2:07 PM Daniel Erez <derez(a)redhat.com> wrote:
>
> After invoking transfer_service.finalize, check operation
> status by examining ImageTransferPhase and 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 | 26 +++++++++++++++++++++-----
> 1 file changed, 21 insertions(+), 5 deletions(-)
>
> diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py
> index 2a950c5ed..873c11ce1 100644
> --- a/v2v/rhv-upload-plugin.py
> +++ b/v2v/rhv-upload-plugin.py
> @@ -523,14 +523,30 @@ 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
> + 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")
> + transfer = transfer_service.get()
> +
> + if transfer is None:
Are you sure this is possible? the original code assumed that we
fail with sdk.NotFoundError.
>
> + disk_service = h['disk_service']
> + disk = disk_service.get()
> + if disk.status == types.DiskStatus.OK:
> + continue
If the disk status is OK the upload was finished, so we should break, no?
Yes, should finish. So 'break'.
If the disk status is LOCKED, we should continue. But in this case there is
no point to check the transfer again.
Could add:
if disk.status == types.DiskStatus.LOCKED:
continue
What if the finalize failed, and the disk was deleted? Do we get disk = None
or some exception?
sdk.NotFoundError exception should be thrown.
>
> +
> + if transfer.phase == types.ImageTransferPhase.FINISHED_SUCCESS:
> + debug("finalized after %s seconds", time.time() -
start)
> + break
> +
> + if transfer.phase ==
> types.ImageTransferPhase.FINALIZING_SUCCESS:
> + if time.time() > start + timeout:
> + raise RuntimeError("timed out waiting for transfer
"
> + "to finalize")
> + continue
> +
> + raise RuntimeError("Unexpected transfer phase while
> finalizing "
> + "upload %r" % transfer.phase)
> except sdk.NotFoundError:
> pass
Is this error possible? We need to add debug log here.
I think the logic should be:
while True:
wait
get transfer
if transfer does not exists (None or sdk.NotFoundErro) , break
if transfer is finished, break (success)
if transfer is finalizing:
if timed out, fail
continue
fail with invalid transfer phase
while True:
wait
get disk
if disk does not exists (None or sdk.NotFoundErro), fail
if disk is OK, break (success)
if disk is locked:
if timed out, fail
continue
fail with invalid disk status
This is little bit crazy that all user have to do this.
Should make it simpler indeed. Maybe add it to the example at least or create
some library for reusability. Fo now, I think it's good enough to
check disk's status
and catch NotFoundError exception as an indication for error in finalize
(I'll send a new version for this).
I.e.
disk_id = disk.id
start = time.time()
try:
while True:
time.sleep(1)
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:
debug("transfer finalize failed for disk: %s", disk_id)
pass
We need to change engine so transfer is kept in the database after it finished for
enough
time (1 hour?), so user can wait *only* for the transfer.
Nir
8:50 a.m.
New subject: [PATCH v2] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)
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']
+ 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)
pass
# Write the disk ID file. Only do this on successful completion.
--
9:08 a.m.
New subject: [PATCH v2] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)
On Sun, Mar 17, 2019 at 3:51 PM Daniel Erez <derez(a)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
11:51 a.m.
New subject: [PATCH v3] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)
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:
--
9:05 a.m.
New subject: [PATCH v3] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)
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
6:58 p.m.
New subject: [PATCH v3] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)
On Thu, Aug 8, 2019 at 5:05 PM Richard W.M. Jones <rjones(a)redhat.com> wrote:
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)
Maybe this was the real error? (using , instead of %)
> + 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
This looks like failure flow - but there is no info here on the real
failure. We need to understand
what was that 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.
']
I think this error means that the disk is currently busy, probably because
of the real error.
Ilanit, can you share complete virt-v2v and daemon logs?
There is a surprising behavior in the image transfer API - you create a
disk, and start
a transfer session with that disk. However once you started a the transfer,
it owns
the disk, and it will delete it in case of failures, so you don't need to
delete it yourself.
I guess you need something like
h["owns_disk"] = True
After creating the disk, and once the transfer was started, set it to False.
In your cleanup flow, delete the disk only if you still own it.
The other issue here is that the error during close is hiding the real
error. This is
a common problem in python 2, and the solution is typically to catch all
exceptions
in the cleanup flow and log them, and make sure the original error is
raised and
logged by the top error handler.
Nir
3:20 a.m.
New subject: [PATCH v3] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)
On Fri, Aug 09, 2019 at 02:58:18AM +0300, Nir Soffer wrote:
On Thu, Aug 8, 2019 at 5:05 PM Richard W.M. Jones
<rjones(a)redhat.com> wrote:
> > + if disk.status == types.DiskStatus.OK:
> > + debug("finalized after %s seconds", time.time()
-
> start)
>
Maybe this was the real error? (using , instead of %)
I fixed this in a later build. However the error we're talking about
here seems to be unrelated to it.
...
> ', ' 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.
> ']
>
I think this error means that the disk is currently busy, probably because
of the real error.
Ilanit, can you share complete virt-v2v and daemon logs?
These are quite large so I uploaded them here:
http://oirase.annexia.org/tmp/v2v-import-20190808T125134-439694.log
http://oirase.annexia.org/tmp/v2v-import-20190808T125134-439694-wrapper.log
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
6:55 p.m.
New subject: [PATCH v3] v2v: rhv-upload-plugin - improve wait logic after finalize (RHBZ#1680361)
On Fri, Aug 9, 2019 at 11:20 AM Richard W.M. Jones <rjones(a)redhat.com>
wrote:
On Fri, Aug 09, 2019 at 02:58:18AM +0300, Nir Soffer wrote:
> On Thu, Aug 8, 2019 at 5:05 PM Richard W.M. Jones <rjones(a)redhat.com>
wrote:
>
> > > + if disk.status == types.DiskStatus.OK:
> > > + debug("finalized after %s seconds",
time.time()
-
> > start)
> >
>
> Maybe this was the real error? (using , instead of %)
I fixed this in a later build. However the error we're talking about
here seems to be unrelated to it.
...
> > ', ' 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.
> > ']
> >
>
> I think this error means that the disk is currently busy, probably
because
> of the real error.
>
> Ilanit, can you share complete virt-v2v and daemon logs?
These are quite large so I uploaded them here:
http://oirase.annexia.org/tmp/v2v-import-20190808T125134-439694.log
I think what we see here is that upload was successful:
nbdkit: python[1]: debug: flush
nbdkit: python[1]: debug: flush
nbdkit: python[1]: debug: client sent disconnect command, closing connection
nbdkit: python[1]: debug: close
...
virtual copying rate: 649.6 M bits/sec
...
[1729.6] Creating output metadata
virt-v2v: error: transfer of disk 1/1 failed, see earlier error messages
...
nbdkit: python[1]: error: /var/tmp/v2v.sZm0my/rhv-upload-plugin.py: close:
error: ['Traceback (most recent call last):\n', ' File
"/var/tmp/v2v.sZm0my/rhv-upload-plugin.py", line 577, in close\n', '
File
"/var/tmp/v2v.sZm0my/rhv-upload-plugin.py", line 516, in
delete_disk_on_failure\n', ' File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/services.py", line 37334, in
remove\n self._internal_remove(headers, query, wait)\n', ' File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 271, in
_internal_remove\n return future.wait() if wait else future\n', ' File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 55, in
wait\n return self._code(response)\n', ' File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 268, in
callback\n self._check_fault(response)\n', ' File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 132, in
_check_fault\n self._raise_error(response, body)\n', ' File
"/usr/lib64/python2.7/site-packages/ovirtsdk4/service.py", line 118, in
_raise_error\n raise error\n', '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.\n']
But we had a bug in the logging code:
debug("fmt", value)
This raised when we discovered that the upload was successful, and we tried
to cleanup
after errors by deleting the disk. This failed because the disk is still
being used by engine
at this point.
Base on what Ilanit wrote in the other thread, after fixing the debug()
call this works.
http://oirase.annexia.org/tmp/v2v-import-20190808T125134-439694-wrapper.log
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
1931
days inactive
2076
days old
9 comments
3 participants
participants (3)
-
Daniel Erez -
Nir Soffer -
Richard W.M. Jones