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?