Libguestfs - Nov 2019 - Re: [PATCH v2 00/11] rvh-upload: Various fixes and cleanups

On Tue, Nov 19, 2019 at 01:48:31PM +0100, Martin Kletzander
wrote:
>On Tue, Nov 19, 2019 at 02:24:11PM +0200, Nir Soffer wrote:
>>On Tue, Nov 19, 2019 at 2:16 PM Martin Kletzander
<mkletzan@redhat.com> wrote:
>>> On Tue, Nov 19, 2019 at 01:14:23PM +0200, Nir Soffer wrote:
>>> >On Tue, Nov 19, 2019 at 11:17 AM Martin Kletzander
<mkletzan@redhat.com> wrote:
>>> >>
>>> >> Traceback (most recent call last):
>>> >>   File
"/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 97, in
>>> open
>>> >>     transfer_service.cancel()
>>> >> NameError: name 'transfer_service' is not defined
>>> >
>>> >Does this fix the error for you?
>>> >
>>>
https://github.com/nirs/virt-v2v/commit/2f93dbffad81a26445831293ecac213eadffbd57
>>> >
>>> >I did not test it yet.
>>> >
>>>
>>> If I remove the stray `def finalize_transfer(...)` it works, yes.
>>>
>>
>>Right, belongs to the next patch.
>>
>>
>>> In the meantime I managed to fix the original issue (which I needed
to
>>> revert to
>>> test this patch =) ), thankfully it was just caused by my oVirt
host setup.
>>>
>>> Unfortunately I am getting another issue.  Now nbdkit fails after
all the
>>> data
>>> is written and it is trying to write the disk id file.  I'm
getting "No
>>> such
>>> file or directory", so because it is writing to that file
I'm assuming the
>>> directory does not exist.  On the other hand it *must* exists
because it's
>>> the
>>> same one where the python scripts are saved.  So I need to debug
more.
>>>
>>
>>This works for me, are you running a modified plugin?
>
>No, it is a current master of virt-v2v.  But don't worry about it now. 
It is
>most probably something with my setup again.  Even though it worked before
and
>these issues started showing up after an update to virt-v2v.  I'll try
with
>current master of nbdkit, libguestfs and virt-v2v first and if that fails
I'll
>try different version of virt-v2v and then start debugging it from the
script
>itself.  It is a bit tedious as I need to modify the script in-tree, upload
it
>to the server, build it there, install it, then run virt-v2v-wrapper
(that's how
>I'm testing it now) and then inspect the logs on that remote machine.
Actually looking at the whole log what I'm getting is:

nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py: flush:
error: ['Traceback (most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 298, in flush\n
http.request("PATCH", h[\'path\'], body=buf,
headers=headers)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1252, in request\n   
self._send_request(method, url, body, headers, encode_chunked)\n', ' 
File "/usr/lib64/python3.7/http/client.py", line 1263, in
_send_request\n    self.putrequest(method, url, **skips)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1108, in putrequest\n   
raise CannotSendRequest(self.__state)\n',
'http.client.CannotSendRequest: Request-sent\n']
nbdkit: python[1]: debug: sending error reply: Input/output error
nbdkit: python[1]: debug: python: flush
nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py: flush:
error: ['Traceback (most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 298, in flush\n
http.request("PATCH", h[\'path\'], body=buf,
headers=headers)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1252, in request\n   
self._send_request(method, url, body, headers, encode_chunked)\n', ' 
File "/usr/lib64/python3.7/http/client.py", line 1263, in
_send_request\n    self.putrequest(method, url, **skips)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1108, in putrequest\n   
raise CannotSendRequest(self.__state)\n',
'http.client.CannotSendRequest: Request-sent\n']
nbdkit: python[1]: debug: sending error reply: Input/output error

...

and then after couple of lines, when it is actually closing I get:

...

finalized after 8.060538530349731 seconds
nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py: close:
error: ['Traceback (most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 362, in
close\n', "FileNotFoundError: [Errno 2] No such file or directory:
'/var/tmp/rhvupload.jngN1W/diskid.0'\n"]
nbdkit: debug: python: unload plugin

So it might be because virt-v2v already removed that directory and did not wait
for nbdkit to completely end.  I'm testing with older commit of virt-v2v
now.

Martin

On Tue, Nov 19, 2019 at 02:36:36PM +0100, Martin Kletzander
wrote:
> nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
close: error: ['Traceback (most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 362, in
close\n', "FileNotFoundError: [Errno 2] No such file or directory:
'/var/tmp/rhvupload.jngN1W/diskid.0'\n"]
> nbdkit: debug: python: unload plugin
>
> So it might be because virt-v2v already removed that directory and
> did not wait for nbdkit to completely end.  I'm testing with older
> commit of virt-v2v now.
This is very likely.

Shutdown on error is complicated.  Virt-v2v starts one or more nbdkit
processes in the background and then simply runs “qemu-img convert”.
If nbdkit notices an error then it returns an error over NBD to
qemu-img.  If qemu-img exits with an error then virt-v2v exits.

Before virt-v2v exits, it runs any exit handlers.  In particular if
you're using OCaml's at_exit, C's atexit(3) or wrappers like
Tools_utils.unlink_on_exit or Tools_utils.rmdir_on_exit, then those
have already run before nbdkit starts to shut down.

Nbdkit should receive a signal from the kernel when its parent process
(virt-v2v) goes away, because we're using prctl + PR_SET_PDEATHSIG +
SIGTERM (via ‘nbdkit --exit-with-parent’).  Note this happens *after*
virt-v2v has fully exited.

Hence what I say about the above being likely, since
rmdir_on_exit "/var/tmp/rhvupload.XXXXXX" is being called from
virt-v2v on exit:

 
https://github.com/libguestfs/virt-v2v/blob/b8b9dcc90dbd91aec4b6bb82dd511d453f77aab9/v2v/output_rhv_upload.ml#L104

To further complicate things, in nbdkit < 1.16 the shutdown path from
a signal was pretty racy.  nbdkit 1.16 attempts to fix the shutdown
path so that we now properly wait for all threads to exit before
exiting nbdkit.  The upstream commit is:

 
https://github.com/libguestfs/nbdkit/commit/07806d6d5511bb5da2dfae2bf0009a5edd992f3a

nbdkit 1.16 is available in Fedora 31+ and RHEL 8.2 AV (out of brew at
the moment), and while it probably won't make any difference here, if
possible you should upgrade to it.  It's fully backwards compatible.

Oh and finally if we're running in a systemd unit, then systemd might
try to kill everything when virt-v2v exits (but before nbdkit exits)
and it's anyone's guess what happens then.  Good luck!  Probably best
to try to make the code as bulletproof as possible so it doesn't
depend on clean ups always running correctly.

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, Nov 19, 2019 at 3:36 PM Martin Kletzander <mkletzan@redhat.com>
wrote:
> On Tue, Nov 19, 2019 at 01:48:31PM +0100, Martin Kletzander wrote:
> >On Tue, Nov 19, 2019 at 02:24:11PM +0200, Nir Soffer wrote:
> >>On Tue, Nov 19, 2019 at 2:16 PM Martin Kletzander
<mkletzan@redhat.com>
> wrote:
> >>> On Tue, Nov 19, 2019 at 01:14:23PM +0200, Nir Soffer wrote:
> >>> >On Tue, Nov 19, 2019 at 11:17 AM Martin Kletzander <
> mkletzan@redhat.com> wrote:
> >>> >>
> >>> >> Traceback (most recent call last):
> >>> >>   File
"/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 97, in
> >>> open
> >>> >>     transfer_service.cancel()
> >>> >> NameError: name 'transfer_service' is not
defined
> >>> >
> >>> >Does this fix the error for you?
> >>> >
> >>>
>
https://github.com/nirs/virt-v2v/commit/2f93dbffad81a26445831293ecac213eadffbd57
> >>> >
> >>> >I did not test it yet.
> >>> >
> >>>
> >>> If I remove the stray `def finalize_transfer(...)` it works,
yes.
> >>>
> >>
> >>Right, belongs to the next patch.
> >>
> >>
> >>> In the meantime I managed to fix the original issue (which I
needed to
> >>> revert to
> >>> test this patch =) ), thankfully it was just caused by my
oVirt host
> setup.
> >>>
> >>> Unfortunately I am getting another issue.  Now nbdkit fails
after all
> the
> >>> data
> >>> is written and it is trying to write the disk id file. 
I'm getting "No
> >>> such
> >>> file or directory", so because it is writing to that file
I'm assuming
> the
> >>> directory does not exist.  On the other hand it *must* exists
because
> it's
> >>> the
> >>> same one where the python scripts are saved.  So I need to
debug more.
> >>>
> >>
> >>This works for me, are you running a modified plugin?
> >
> >No, it is a current master of virt-v2v.  But don't worry about it
now.
> It is
> >most probably something with my setup again.  Even though it worked
> before and
> >these issues started showing up after an update to virt-v2v.  I'll
try
> with
> >current master of nbdkit, libguestfs and virt-v2v first and if that
fails
> I'll
> >try different version of virt-v2v and then start debugging it from the
> script
> >itself.  It is a bit tedious as I need to modify the script in-tree,
> upload it
> >to the server, build it there, install it, then run virt-v2v-wrapper
> (that's how
> >I'm testing it now) and then inspect the logs on that remote
machine.
>
> Actually looking at the whole log what I'm getting is:
>
> nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
> flush: error: ['Traceback (most recent call last):\n', '  File
> "/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 298, in
flush\n
> http.request("PATCH", h[\'path\'], body=buf,
headers=headers)\n', '  File
> "/usr/lib64/python3.7/http/client.py", line 1252, in request\n
> self._send_request(method, url, body, headers, encode_chunked)\n',
'  File
> "/usr/lib64/python3.7/http/client.py", line 1263, in
_send_request\n
> self.putrequest(method, url, **skips)\n', '  File
> "/usr/lib64/python3.7/http/client.py", line 1108, in putrequest\n
raise
> CannotSendRequest(self.__state)\n', 'http.client.CannotSendRequest:
> Request-sent\n']
>
Looks like you cannot communicate with imageio daemon - this is fatal error
that should fail the
upload.
...
and then after couple of lines, when it is actually closing I get:
>
> ...
>
> finalized after 8.060538530349731 seconds
>
But we tried to finallize the transfer instead of cancel it.

> nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
> close: error: ['Traceback (most recent call last):\n', '  File
> "/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 362, in
close\n',
> "FileNotFoundError: [Errno 2] No such file or directory:
> '/var/tmp/rhvupload.jngN1W/diskid.0'\n"]
> nbdkit: debug: python: unload plugin
>
> So it might be because virt-v2v already removed that directory and did not
> wait
> for nbdkit to completely end.  I'm testing with older commit of
virt-v2v
> now.
>
flush() failure probably caused qemu-img to fai, and virt-v2v failed and
cleaned up
which is expected.

I think the issue is incorrect error handling in the flush() and other
handlers:

288 def flush(h):
289     http = h['http']
290
291     # Construct the JSON request for flushing.
292     buf = json.dumps({'op': "flush"}).encode()
293
294     headers = {"Content-Type": "application/json",
295                "Content-Length": str(len(buf))}
296
297     http.request("PATCH", h['path'], body=buf,
headers=headers)

If this raised (like in your traceback, we don't set h['failed'] =
True

299     r = http.getresponse()
300     if r.status != 200:
301         request_failed(h, r, "could not flush")
302
303     r.read()

Same here.

Same issue in all handlers. We should handle all errors in the handlers.

But the root cause is something else - why you cannot communicate with
imageio daemon?

On Tue, Nov 19, 2019 at 02:36:36PM +0100, Martin Kletzander
wrote:
>On Tue, Nov 19, 2019 at 01:48:31PM +0100, Martin Kletzander wrote:
>>On Tue, Nov 19, 2019 at 02:24:11PM +0200, Nir Soffer wrote:
>>>On Tue, Nov 19, 2019 at 2:16 PM Martin Kletzander
<mkletzan@redhat.com> wrote:
>>>> On Tue, Nov 19, 2019 at 01:14:23PM +0200, Nir Soffer wrote:
>>>> >On Tue, Nov 19, 2019 at 11:17 AM Martin Kletzander
<mkletzan@redhat.com> wrote:
>>>> >>
>>>> >> Traceback (most recent call last):
>>>> >>   File
"/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 97, in
>>>> open
>>>> >>     transfer_service.cancel()
>>>> >> NameError: name 'transfer_service' is not
defined
>>>> >
>>>> >Does this fix the error for you?
>>>> >
>>>>
https://github.com/nirs/virt-v2v/commit/2f93dbffad81a26445831293ecac213eadffbd57
>>>> >
>>>> >I did not test it yet.
>>>> >
>>>>
>>>> If I remove the stray `def finalize_transfer(...)` it works,
yes.
>>>>
>>>
>>>Right, belongs to the next patch.
>>>
>>>
>>>> In the meantime I managed to fix the original issue (which I
needed to
>>>> revert to
>>>> test this patch =) ), thankfully it was just caused by my oVirt
host setup.
>>>>
>>>> Unfortunately I am getting another issue.  Now nbdkit fails
after all the
>>>> data
>>>> is written and it is trying to write the disk id file.  I'm
getting "No
>>>> such
>>>> file or directory", so because it is writing to that file
I'm assuming the
>>>> directory does not exist.  On the other hand it *must* exists
because it's
>>>> the
>>>> same one where the python scripts are saved.  So I need to
debug more.
>>>>
>>>
>>>This works for me, are you running a modified plugin?
>>
>>No, it is a current master of virt-v2v.  But don't worry about it
now.  It is
>>most probably something with my setup again.  Even though it worked
before and
>>these issues started showing up after an update to virt-v2v.  I'll
try with
>>current master of nbdkit, libguestfs and virt-v2v first and if that
fails I'll
>>try different version of virt-v2v and then start debugging it from the
script
>>itself.  It is a bit tedious as I need to modify the script in-tree,
upload it
>>to the server, build it there, install it, then run virt-v2v-wrapper
(that's how
>>I'm testing it now) and then inspect the logs on that remote
machine.
>
>Actually looking at the whole log what I'm getting is:
>
>nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
flush: error: ['Traceback (most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 298, in flush\n
http.request("PATCH", h[\'path\'], body=buf,
headers=headers)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1252, in request\n   
self._send_request(method, url, body, headers, encode_chunked)\n', ' 
File "/usr/lib64/python3.7/http/client.py", line 1263, in
_send_request\n    self.putrequest(method, url, **skips)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1108, in putrequest\n   
raise CannotSendRequest(self.__state)\n',
'http.client.CannotSendRequest: Request-sent\n']
>nbdkit: python[1]: debug: sending error reply: Input/output error
>nbdkit: python[1]: debug: python: flush
>nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
flush: error: ['Traceback (most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 298, in flush\n
http.request("PATCH", h[\'path\'], body=buf,
headers=headers)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1252, in request\n   
self._send_request(method, url, body, headers, encode_chunked)\n', ' 
File "/usr/lib64/python3.7/http/client.py", line 1263, in
_send_request\n    self.putrequest(method, url, **skips)\n', '  File
"/usr/lib64/python3.7/http/client.py", line 1108, in putrequest\n   
raise CannotSendRequest(self.__state)\n',
'http.client.CannotSendRequest: Request-sent\n']
>nbdkit: python[1]: debug: sending error reply: Input/output error
>
>...
>
>and then after couple of lines, when it is actually closing I get:
>
>...
>
>finalized after 8.060538530349731 seconds
>nbdkit: python[1]: error: /var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
close: error: ['Traceback (most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 362, in
close\n', "FileNotFoundError: [Errno 2] No such file or directory:
'/var/tmp/rhvupload.jngN1W/diskid.0'\n"]
>nbdkit: debug: python: unload plugin
>
>So it might be because virt-v2v already removed that directory and did not
wait
>for nbdkit to completely end.  I'm testing with older commit of virt-v2v
now.
>
Nope, still getting the same error even with old commit that definitely worked,
just different lines in the http PATCH request.  I don't know what to try
next,
but at least we know it's not related to your patches.

Thanks for your time :)
>Martin

On Tue, Nov 19, 2019 at 02:14:32PM +0000, Richard W.M. Jones
wrote:
>On Tue, Nov 19, 2019 at 02:36:36PM +0100, Martin Kletzander wrote:
>> nbdkit: python[1]: error:
/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py: close: error: ['Traceback
(most recent call last):\n', '  File
"/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 362, in
close\n', "FileNotFoundError: [Errno 2] No such file or directory:
'/var/tmp/rhvupload.jngN1W/diskid.0'\n"]
>> nbdkit: debug: python: unload plugin
>>
>> So it might be because virt-v2v already removed that directory and
>> did not wait for nbdkit to completely end.  I'm testing with older
>> commit of virt-v2v now.
>
>This is very likely.
>
>Shutdown on error is complicated.  Virt-v2v starts one or more nbdkit
>processes in the background and then simply runs “qemu-img convert”.
>If nbdkit notices an error then it returns an error over NBD to
>qemu-img.  If qemu-img exits with an error then virt-v2v exits.
>
>Before virt-v2v exits, it runs any exit handlers.  In particular if
>you're using OCaml's at_exit, C's atexit(3) or wrappers like
>Tools_utils.unlink_on_exit or Tools_utils.rmdir_on_exit, then those
>have already run before nbdkit starts to shut down.
>
>Nbdkit should receive a signal from the kernel when its parent process
>(virt-v2v) goes away, because we're using prctl + PR_SET_PDEATHSIG +
>SIGTERM (via ‘nbdkit --exit-with-parent’).  Note this happens *after*
>virt-v2v has fully exited.
>
>Hence what I say about the above being likely, since
>rmdir_on_exit "/var/tmp/rhvupload.XXXXXX" is being called from
>virt-v2v on exit:
>
> 
https://github.com/libguestfs/virt-v2v/blob/b8b9dcc90dbd91aec4b6bb82dd511d453f77aab9/v2v/output_rhv_upload.ml#L104
>
>To further complicate things, in nbdkit < 1.16 the shutdown path from
>a signal was pretty racy.  nbdkit 1.16 attempts to fix the shutdown
>path so that we now properly wait for all threads to exit before
>exiting nbdkit.  The upstream commit is:
>
> 
https://github.com/libguestfs/nbdkit/commit/07806d6d5511bb5da2dfae2bf0009a5edd992f3a
>
>nbdkit 1.16 is available in Fedora 31+ and RHEL 8.2 AV (out of brew at
>the moment), and while it probably won't make any difference here, if
>possible you should upgrade to it.  It's fully backwards compatible.
>
>Oh and finally if we're running in a systemd unit, then systemd might
>try to kill everything when virt-v2v exits (but before nbdkit exits)
>and it's anyone's guess what happens then.  Good luck!  Probably
best
>to try to make the code as bulletproof as possible so it doesn't
>depend on clean ups always running correctly.
>
I am running nbdkit from current master there, so that should be fine.  But
since it is ran by virt-v2v-wrapper on a fedora VM inside oVirt, it is running
under systemd unit.

I should say this is not the main issue, it's just something that happens on
a
clean-up path after another error has happened.
>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, Nov 19, 2019 at 04:14:45PM +0200, Nir Soffer
wrote:
>On Tue, Nov 19, 2019 at 3:36 PM Martin Kletzander
<mkletzan@redhat.com>
>wrote:
>
>> On Tue, Nov 19, 2019 at 01:48:31PM +0100, Martin Kletzander wrote:
>> >On Tue, Nov 19, 2019 at 02:24:11PM +0200, Nir Soffer wrote:
>> >>On Tue, Nov 19, 2019 at 2:16 PM Martin Kletzander
<mkletzan@redhat.com>
>> wrote:
>> >>> On Tue, Nov 19, 2019 at 01:14:23PM +0200, Nir Soffer
wrote:
>> >>> >On Tue, Nov 19, 2019 at 11:17 AM Martin Kletzander
<
>> mkletzan@redhat.com> wrote:
>> >>> >>
>> >>> >> Traceback (most recent call last):
>> >>> >>   File
"/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 97, in
>> >>> open
>> >>> >>     transfer_service.cancel()
>> >>> >> NameError: name 'transfer_service' is not
defined
>> >>> >
>> >>> >Does this fix the error for you?
>> >>> >
>> >>>
>>
https://github.com/nirs/virt-v2v/commit/2f93dbffad81a26445831293ecac213eadffbd57
>> >>> >
>> >>> >I did not test it yet.
>> >>> >
>> >>>
>> >>> If I remove the stray `def finalize_transfer(...)` it
works, yes.
>> >>>
>> >>
>> >>Right, belongs to the next patch.
>> >>
>> >>
>> >>> In the meantime I managed to fix the original issue (which
I needed to
>> >>> revert to
>> >>> test this patch =) ), thankfully it was just caused by my
oVirt host
>> setup.
>> >>>
>> >>> Unfortunately I am getting another issue.  Now nbdkit
fails after all
>> the
>> >>> data
>> >>> is written and it is trying to write the disk id file. 
I'm getting "No
>> >>> such
>> >>> file or directory", so because it is writing to that
file I'm assuming
>> the
>> >>> directory does not exist.  On the other hand it *must*
exists because
>> it's
>> >>> the
>> >>> same one where the python scripts are saved.  So I need to
debug more.
>> >>>
>> >>
>> >>This works for me, are you running a modified plugin?
>> >
>> >No, it is a current master of virt-v2v.  But don't worry about
it now.
>> It is
>> >most probably something with my setup again.  Even though it worked
>> before and
>> >these issues started showing up after an update to virt-v2v. 
I'll try
>> with
>> >current master of nbdkit, libguestfs and virt-v2v first and if that
fails
>> I'll
>> >try different version of virt-v2v and then start debugging it from
the
>> script
>> >itself.  It is a bit tedious as I need to modify the script
in-tree,
>> upload it
>> >to the server, build it there, install it, then run
virt-v2v-wrapper
>> (that's how
>> >I'm testing it now) and then inspect the logs on that remote
machine.
>>
>> Actually looking at the whole log what I'm getting is:
>>
>> nbdkit: python[1]: error:
/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
>> flush: error: ['Traceback (most recent call last):\n', ' 
File
>> "/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 298,
in flush\n
>> http.request("PATCH", h[\'path\'], body=buf,
headers=headers)\n', '  File
>> "/usr/lib64/python3.7/http/client.py", line 1252, in
request\n
>> self._send_request(method, url, body, headers, encode_chunked)\n',
'  File
>> "/usr/lib64/python3.7/http/client.py", line 1263, in
_send_request\n
>> self.putrequest(method, url, **skips)\n', '  File
>> "/usr/lib64/python3.7/http/client.py", line 1108, in
putrequest\n    raise
>> CannotSendRequest(self.__state)\n',
'http.client.CannotSendRequest:
>> Request-sent\n']
>>
>
>Looks like you cannot communicate with imageio daemon - this is fatal error
>that should fail the
>upload.
>...
>and then after couple of lines, when it is actually closing I get:
>
>>
>> ...
>>
>> finalized after 8.060538530349731 seconds
>>
>
>But we tried to finallize the transfer instead of cancel it.
>
>
>> nbdkit: python[1]: error:
/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py:
>> close: error: ['Traceback (most recent call last):\n', ' 
File
>> "/var/tmp/rhvupload.jngN1W/rhv-upload-plugin.py", line 362,
in close\n',
>> "FileNotFoundError: [Errno 2] No such file or directory:
>> '/var/tmp/rhvupload.jngN1W/diskid.0'\n"]
>> nbdkit: debug: python: unload plugin
>>
>> So it might be because virt-v2v already removed that directory and did
not
>> wait
>> for nbdkit to completely end.  I'm testing with older commit of
virt-v2v
>> now.
>>
>
>flush() failure probably caused qemu-img to fai, and virt-v2v failed and
>cleaned up
>which is expected.
>
>I think the issue is incorrect error handling in the flush() and other
>handlers:
>
>288 def flush(h):
>289     http = h['http']
>290
>291     # Construct the JSON request for flushing.
>292     buf = json.dumps({'op': "flush"}).encode()
>293
>294     headers = {"Content-Type": "application/json",
>295                "Content-Length": str(len(buf))}
>296
>297     http.request("PATCH", h['path'], body=buf,
headers=headers)
>
>If this raised (like in your traceback, we don't set h['failed']
= True
>
>299     r = http.getresponse()
>300     if r.status != 200:
>301         request_failed(h, r, "could not flush")
>302
>303     r.read()
>
>Same here.
>
>Same issue in all handlers. We should handle all errors in the handlers.
>
>But the root cause is something else - why you cannot communicate with
>imageio daemon?
That is something I would love to find out, but I don't know what to try
next.
I'm probably tired of spending a whole day on this, especially when I just
need
it to test something else =)