[PATCH v2 00/11] rvh-upload: Various fixes and cleanups

[PATCH 0/2] rhv-upload: Complete...

Building libguestfs from git

Nir Soffer

Monday, 18 November 2019 Mon, 18 Nov '19

3:53 p.m.

This series extract oVirt SDK and imageio code to make it eaiser to follow the code and improve error handing in open() and close(). Tested with virt-v2v master. Changes since v1: - Rebase on merged patches from v1 - Fix regression introduced by "rhv-upload: Fix cleanup after errors" - Remove "rhv-upload: Try to remove disk on timeout" since it cannot succeed - Add more context in debug error logs - Use disk_id instead of disk.id in close() v1 was here: https://www.redhat.com/archives/libguestfs/2019-November/msg00060.html Nir Soffer (11): rhv-upload: Cancel transfer if finalize failed rhv-upload: Keep disk_id in handle rhv-upload: Show disk id in error message rhv-upload: Don't keep transfer_service in handle rhv-upload: Get host before creating disk rhv-upload: Extract create_transfer() function rhv-upload: Show transfer id in error message rhv-upload: Extract imageio helpers rhv-upload: Extract get_options() helper rhv-upload: Extract optimize_http() helper rhv-upload: Clean up username and password v2v/rhv-upload-plugin.py | 325 ++++++++++++++++++++++----------------- 1 file changed, 184 insertions(+), 141 deletions(-) -- 2.21.0

Show replies by date

Nir Soffer

Monday, 18 November Mon, 18 Nov

3:53 p.m.

New subject: [PATCH v2 01/11] rhv-upload: Cancel transfer if finalize failed

If engine fails to finalize the transfer, for example due to inaccessible storage, it will move to "paused by system" state and keep the disk. We need to cancel the transfer to have the disk removed. Thanks: Daniel Erez. --- v2v/rhv-upload-plugin.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 9b433bd7..114d5d55 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -458,6 +458,11 @@ def close(h): with builtins.open(params['diskid_file'], 'w') as fp: fp.write(disk.id) + except: + # If oVirt engine fails to finalize the transfer, it will pause the + # transfer and keep the disk. + transfer_service.cancel() + raise finally: connection.close() -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 02/11] rhv-upload: Keep disk_id in handle

We kept the disk object for its id. Replace it with the disk id. This can make debugging easier when we log the handle. --- v2v/rhv-upload-plugin.py | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 114d5d55..24944005 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -205,7 +205,7 @@ def open(readonly): 'can_trim': can_trim, 'can_zero': can_zero, 'connection': connection, - 'disk': disk, + 'disk_id': disk.id, 'failed': False, 'highestwrite': 0, 'http': http, @@ -425,7 +425,7 @@ def close(h): return try: - disk = h['disk'] + disk_id = h['disk_id'] transfer_service.finalize() @@ -435,9 +435,8 @@ def close(h): # waiting for the transfer object to cease to exist, which # falls through to the exception case and then we can # continue. - disk_id = disk.id disk_service = ( - connection.system_service().disks_service().disk_service(disk.id)) + connection.system_service().disks_service().disk_service(disk_id)) start = time.time() try: while True: @@ -456,7 +455,7 @@ def close(h): # Write the disk ID file. Only do this on successful completion. with builtins.open(params['diskid_file'], 'w') as fp: - fp.write(disk.id) + fp.write(disk_id) except: # If oVirt engine fails to finalize the transfer, it will pause the -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 03/11] rhv-upload: Show disk id in error message

Having more context in errors makes debugging easier. --- v2v/rhv-upload-plugin.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 24944005..146522fe 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -579,6 +579,7 @@ def create_disk(connection): if disk.status == types.DiskStatus.OK: break if time.time() > endt: - raise RuntimeError("timed out waiting for disk to become unlocked") + raise RuntimeError( + "timed out waiting for disk %s to become unlocked" % disk.id) return disk -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 04/11] rhv-upload: Don't keep transfer_service in handle

Instead of keeping the transfer_service in the handle, extract the transfer service object in close() using the transfer id. This will make it easier to extract the code for creating a transfer out of open(). --- v2v/rhv-upload-plugin.py | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 146522fe..11f18041 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -206,13 +206,12 @@ def open(readonly): 'can_zero': can_zero, 'connection': connection, 'disk_id': disk.id, + 'transfer': transfer, 'failed': False, 'highestwrite': 0, 'http': http, 'needs_auth': needs_auth, 'path': destination_url.path, - 'transfer': transfer, - 'transfer_service': transfer_service, } def can_trim(h): @@ -405,7 +404,11 @@ def flush(h): def close(h): http = h['http'] connection = h['connection'] - transfer_service = h['transfer_service'] + transfer = h['transfer'] + + transfer_service = (connection.system_service() + .image_transfers_service() + .image_transfer_service(transfer.id)) # This is sometimes necessary because python doesn't set up # sys.stderr to be line buffered and so debug, errors or -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 05/11] rhv-upload: Get host before creating disk

If getting the host object raised, we forgot to remove the disk. Getting the host object before creating the disk avoids the error handling, and will fail faster on errors, without waiting until the disk is ready. This will help to extract the code for creating transfer out of open(). --- v2v/rhv-upload-plugin.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 11f18041..78e396aa 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -77,14 +77,15 @@ def open(readonly): insecure = params['insecure'], ) + # Use the local host is possible. + host = find_host(connection) if params['rhv_direct'] else None disk = create_disk(connection) # Get a reference to the transfer service. system_service = connection.system_service() transfers_service = system_service.image_transfers_service() - # Create a new image transfer, using the local host is possible. - host = find_host(connection) if params['rhv_direct'] else None + # Create a new image transfer. transfer = transfers_service.add( types.ImageTransfer( disk = types.Disk(id = disk.id), -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 06/11] rhv-upload: Extract create_transfer() function

Creating a transfer is complex and clumsy. Extracting the code to a helper function will clean up open() and make it easier to improve error handling. --- v2v/rhv-upload-plugin.py | 77 ++++++++++++++++++++++------------------ 1 file changed, 42 insertions(+), 35 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 78e396aa..c88c6990 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -80,41 +80,7 @@ def open(readonly): # Use the local host is possible. host = find_host(connection) if params['rhv_direct'] else None disk = create_disk(connection) - - # Get a reference to the transfer service. - system_service = connection.system_service() - transfers_service = system_service.image_transfers_service() - - # Create a new image transfer. - transfer = transfers_service.add( - types.ImageTransfer( - disk = types.Disk(id = disk.id), - host = host, - inactivity_timeout = 3600, - ) - ) - - # At this point the transfer owns the disk and will delete the disk if the - # transfer is canceled, or if finalizing the transfer fails. - - debug("transfer.id = %r" % transfer.id) - - # Get a reference to the created transfer service. - transfer_service = transfers_service.image_transfer_service(transfer.id) - - # After adding a new transfer for the disk, the transfer's status - # will be INITIALIZING. Wait until the init phase is over. The - # actual transfer can start when its status is "Transferring". - endt = time.time() + timeout - while True: - transfer = transfer_service.get() - if transfer.phase != types.ImageTransferPhase.INITIALIZING: - break - if time.time() > endt: - transfer_service.cancel() - raise RuntimeError("timed out waiting for transfer status " - "!= INITIALIZING") - time.sleep(1) + transfer = create_transfer(connection, disk, host) # Now we have permission to start the transfer. if params['rhv_direct']: @@ -587,3 +553,44 @@ def create_disk(connection): "timed out waiting for disk %s to become unlocked" % disk.id) return disk + +def create_transfer(connection, disk, host): + """ + Create image transfer and wait until the transfer is ready. + + Returns a transfer object. + """ + system_service = connection.system_service() + transfers_service = system_service.image_transfers_service() + + transfer = transfers_service.add( + types.ImageTransfer( + disk = types.Disk(id = disk.id), + host = host, + inactivity_timeout = 3600, + ) + ) + + # At this point the transfer owns the disk and will delete the disk if the + # transfer is canceled, or if finalizing the transfer fails. + + debug("transfer.id = %r" % transfer.id) + + # Get a reference to the created transfer service. + transfer_service = transfers_service.image_transfer_service(transfer.id) + + # After adding a new transfer for the disk, the transfer's status + # will be INITIALIZING. Wait until the init phase is over. The + # actual transfer can start when its status is "Transferring". + endt = time.time() + timeout + while True: + transfer = transfer_service.get() + if transfer.phase != types.ImageTransferPhase.INITIALIZING: + break + if time.time() > endt: + transfer_service.cancel() + raise RuntimeError("timed out waiting for transfer status " + "!= INITIALIZING") + time.sleep(1) + + return transfer -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 07/11] rhv-upload: Show transfer id in error message

--- v2v/rhv-upload-plugin.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index c88c6990..54f44b05 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -589,8 +589,10 @@ def create_transfer(connection, disk, host): break if time.time() > endt: transfer_service.cancel() - raise RuntimeError("timed out waiting for transfer status " - "!= INITIALIZING") + raise RuntimeError( + "timed out waiting for transfer %s status != INITIALIZING" + % transfer.id) + time.sleep(1) return transfer -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 08/11] rhv-upload: Extract imageio helpers

Starting an upload to imageio is complex. Starting extracting helpers to make the flow more clear: - parse_transfer_url(): Select and parse the transfer url. - create_http(): Create http connection for the selected url. Cleanup error handling by adding a try block after creating the transfer. Every error in this try block will cancel the transfer before raising the error. When the refactoring is done, all the code in open() will be protected by this try block. --- v2v/rhv-upload-plugin.py | 74 +++++++++++++++++++++++----------------- 1 file changed, 42 insertions(+), 32 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 54f44b05..16bb6e87 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -80,40 +80,14 @@ def open(readonly): # Use the local host is possible. host = find_host(connection) if params['rhv_direct'] else None disk = create_disk(connection) - transfer = create_transfer(connection, disk, host) - - # Now we have permission to start the transfer. - if params['rhv_direct']: - if transfer.transfer_url is None: - transfer_service.cancel() - raise RuntimeError("direct upload to host not supported, " - "requires ovirt-engine >= 4.2 and only works " - "when virt-v2v is run within the oVirt/RHV " - "environment, eg. on an oVirt node.") - destination_url = urlparse(transfer.transfer_url) - else: - destination_url = urlparse(transfer.proxy_url) - if destination_url.scheme == "https": - context = \ - ssl.create_default_context(purpose = ssl.Purpose.SERVER_AUTH, - cafile = params['rhv_cafile']) - if params['insecure']: - context.check_hostname = False - context.verify_mode = ssl.CERT_NONE - http = HTTPSConnection( - destination_url.hostname, - destination_url.port, - context = context - ) - elif destination_url.scheme == "http": - http = HTTPConnection( - destination_url.hostname, - destination_url.port, - ) - else: + transfer = create_transfer(connection, disk, host) + try: + destination_url = parse_transfer_url(transfer) + http = create_http(destination_url) + except: transfer_service.cancel() - raise RuntimeError("unknown URL scheme (%s)" % destination_url.scheme) + raise # The first request is to fetch the features of the server. @@ -596,3 +570,39 @@ def create_transfer(connection, disk, host): time.sleep(1) return transfer + +# oVirt imageio operations + +def parse_transfer_url(transfer): + """ + Returns a parsed transfer url, preferring direct transfer if possible. + """ + if params['rhv_direct']: + if transfer.transfer_url is None: + raise RuntimeError("direct upload to host not supported, " + "requires ovirt-engine >= 4.2 and only works " + "when virt-v2v is run within the oVirt/RHV " + "environment, eg. on an oVirt node.") + return urlparse(transfer.transfer_url) + else: + return urlparse(transfer.proxy_url) + +def create_http(url): + """ + Create http connection for transfer url. + + Returns HTTPConnction. + """ + if url.scheme == "https": + context = \ + ssl.create_default_context(purpose = ssl.Purpose.SERVER_AUTH, + cafile = params['rhv_cafile']) + if params['insecure']: + context.check_hostname = False + context.verify_mode = ssl.CERT_NONE + + return HTTPSConnection(url.hostname, url.port, context = context) + elif url.scheme == "http": + return HTTPConnection(url.hostname, url.port) + else: + raise RuntimeError("unknown URL scheme (%s)" % url.scheme) -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 09/11] rhv-upload: Extract get_options() helper

Extract the code for sending OPTIONS request and handling response for new and old imageio daemon and proxy to a helper function. The response from imageio is normalized as a dict to make it easier to handle the various combinations. --- v2v/rhv-upload-plugin.py | 93 +++++++++++++++++++++------------------- 1 file changed, 48 insertions(+), 45 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 16bb6e87..6e855610 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -85,73 +85,40 @@ def open(readonly): try: destination_url = parse_transfer_url(transfer) http = create_http(destination_url) + options = get_options(http, destination_url) except: transfer_service.cancel() raise - # The first request is to fetch the features of the server. - - # Authentication was needed only for GET and PUT requests when - # communicating with old imageio-proxy. - needs_auth = not params['rhv_direct'] - - can_flush = False - can_trim = False - can_zero = False - unix_socket = None - - http.request("OPTIONS", destination_url.path) - r = http.getresponse() - data = r.read() - - if r.status == 200: - # New imageio never needs authentication. - needs_auth = False - - j = json.loads(data) - can_flush = "flush" in j['features'] - can_trim = "trim" in j['features'] - can_zero = "zero" in j['features'] - unix_socket = j.get('unix_socket') - - # Old imageio servers returned either 405 Method Not Allowed or - # 204 No Content (with an empty body). If we see that we leave - # all the features as False and they will be emulated. - elif r.status == 405 or r.status == 204: - pass - - else: - transfer_service.cancel() - raise RuntimeError("could not use OPTIONS request: %d: %s" % - (r.status, r.reason)) - - debug("imageio features: flush=%r trim=%r zero=%r unix_socket=%r" % - (can_flush, can_trim, can_zero, unix_socket)) + debug("imageio features: flush=%(can_flush)r trim=%(can_trim)r " + "zero=%(can_zero)r unix_socket=%(unix_socket)r" + % options) # If we are connected to imageio on the local host and the # transfer features a unix_socket then we can reconnect to that. - if host is not None and unix_socket is not None: + if host is not None and options['unix_socket'] is not None: try: - http = UnixHTTPConnection(unix_socket) + http = UnixHTTPConnection(options['unix_socket']) except Exception as e: # Very unlikely failure, but we can recover by using the https # connection. debug("cannot create unix socket connection, using https: %s" % e) else: - debug("optimizing connection using unix socket %r" % unix_socket) + debug("optimizing connection using unix socket %r" + % options['unix_socket']) # Save everything we need to make requests in the handle. return { - 'can_flush': can_flush, - 'can_trim': can_trim, - 'can_zero': can_zero, + 'can_flush': options['can_flush'], + 'can_trim': options['can_trim'], + 'can_zero': options['can_zero'], + 'needs_auth': options['needs_auth'], 'connection': connection, 'disk_id': disk.id, 'transfer': transfer, 'failed': False, 'highestwrite': 0, 'http': http, - 'needs_auth': needs_auth, 'path': destination_url.path, } @@ -606,3 +573,39 @@ def create_http(url): return HTTPConnection(url.hostname, url.port) else: raise RuntimeError("unknown URL scheme (%s)" % url.scheme) + +def get_options(http, url): + """ + Send OPTIONS request to imageio server and return options dict. + """ + http.request("OPTIONS", url.path) + r = http.getresponse() + data = r.read() + + if r.status == 200: + j = json.loads(data) + features = j["features"] + return { + # New imageio never used authentication. + "needs_auth": False, + "can_flush": "flush" in features, + "can_trim": "trim" in features, + "can_zero": "zero" in features, + "unix_socket": j.get('unix_socket'), + } + + elif r.status == 405 or r.status == 204: + # Old imageio servers returned either 405 Method Not Allowed or + # 204 No Content (with an empty body). + return { + # Authentication was required only when using old imageio proxy. + # Can be removed when dropping support for oVirt < 4.2. + "needs_auth": not params['rhv_direct'], + "can_flush": False, + "can_trim": False, + "can_zero": False, + "unix_socket": None, + } + else: + raise RuntimeError("could not use OPTIONS request: %d: %s" % + (r.status, r.reason)) -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 10/11] rhv-upload: Extract optimize_http() helper

Extract the code for optimizing the http connection using unix socket to a helper function. Calling the new function inside the try block ensure that errors creating the connection will cancel the transfer. --- v2v/rhv-upload-plugin.py | 33 ++++++++++++++++++++------------- 1 file changed, 20 insertions(+), 13 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 6e855610..0dcd164d 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -86,6 +86,7 @@ def open(readonly): destination_url = parse_transfer_url(transfer) http = create_http(destination_url) options = get_options(http, destination_url) + http = optimize_http(http, host, options) except: transfer_service.cancel() raise @@ -94,19 +95,6 @@ def open(readonly): "zero=%(can_zero)r unix_socket=%(unix_socket)r" % options) - # If we are connected to imageio on the local host and the - # transfer features a unix_socket then we can reconnect to that. - if host is not None and options['unix_socket'] is not None: - try: - http = UnixHTTPConnection(options['unix_socket']) - except Exception as e: - # Very unlikely failure, but we can recover by using the https - # connection. - debug("cannot create unix socket connection, using https: %s" % e) - else: - debug("optimizing connection using unix socket %r" - % options['unix_socket']) - # Save everything we need to make requests in the handle. return { 'can_flush': options['can_flush'], @@ -609,3 +597,22 @@ def get_options(http, url): else: raise RuntimeError("could not use OPTIONS request: %d: %s" % (r.status, r.reason)) + +def optimize_http(http, host, options): + """ + Return an optimized http connection using unix socket if we are connected + to imageio server on the local host and it features a unix socket. + """ + unix_socket = options['unix_socket'] + + if host is not None and unix_socket is not None: + try: + http = UnixHTTPConnection(unix_socket) + except Exception as e: + # Very unlikely failure, but we can recover by using the https + # connection. + debug("cannot create unix socket connection, using https: %s" % e) + else: + debug("optimizing connection using unix socket %r" % unix_socket) + + return http -- 2.21.0

Nir Soffer

3:53 p.m.

New subject: [PATCH v2 11/11] rhv-upload: Clean up username and password

Extract functions for getting the username and password, cleaning up open(). --- v2v/rhv-upload-plugin.py | 27 ++++++++++++++++----------- 1 file changed, 16 insertions(+), 11 deletions(-) diff --git a/v2v/rhv-upload-plugin.py b/v2v/rhv-upload-plugin.py index 0dcd164d..a2d09458 100644 --- a/v2v/rhv-upload-plugin.py +++ b/v2v/rhv-upload-plugin.py @@ -57,21 +57,26 @@ def debug(s): print(s, file=sys.stderr) sys.stderr.flush() -def open(readonly): - # Parse out the username from the output_conn URL. - parsed = urlparse(params['output_conn']) - username = parsed.username or "admin@internal" - - # Read the password from file. +def read_password(): + """ + Read the password from file. + """ with builtins.open(params['output_password'], 'r') as fp: - password = fp.read() - password = password.rstrip() + data = fp.read() + return data.rstrip() - # Connect to the server. +def parse_username(): + """ + Parse out the username from the output_conn URL. + """ + parsed = urlparse(params['output_conn']) + return parsed.username or "admin@internal" + +def open(readonly): connection = sdk.Connection( url = params['output_conn'], - username = username, - password = password, + username = parse_username(), + password = read_password(), ca_file = params['rhv_cafile'], log = logging.getLogger(), insecure = params['insecure'], -- 2.21.0

Richard W.M. Jones

Tuesday, 19 November Tue, 19 Nov

2:31 a.m.

New subject: [PATCH v2 11/11] rhv-upload: Clean up username and password

As this is all pretty obvious stuff and passes the internal tests (which are not very thorough) I have pushed it. If there are further changes that come about based on review or real world testing we can apply them on top. Thanks, Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-df lists disk usage of guests without needing to install any software inside the virtual machine. Supports Linux and Windows. http://people.redhat.com/~rjones/virt-df/

Martin Kletzander

3:16 a.m.

On Mon, Nov 18, 2019 at 11:53:39PM +0200, Nir Soffer wrote:

...

I'm not sure which one of these is causing it, it sounds like the first one, but basically the cleanup path is probably not checked well. I'm facing a completely different issue currently, but when updated to your version (in a hope that it might either provide more data in the error message or even fix it) I'm now getting a "During handling of the above exception, another exception occurred", which is not a good thing. I think it should be easy to fix and also check for similar issues elsewhere, but I'm now trying to figure out different things that bother me ('No route to host' changing to 'Network unreachable' after the patches even though I can connect everywhere the upload plugin is connecting), so I can't look at it right now. Here's the traceback: Traceback (most recent call last): File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 94, in open options = get_options(http, destination_url) File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 575, in get_options http.request("OPTIONS", url.path) File "/usr/lib64/python3.7/http/client.py", line 1252, in request self._send_request(method, url, body, headers, encode_chunked) File "/usr/lib64/python3.7/http/client.py", line 1298, in _send_request self.endheaders(body, encode_chunked=encode_chunked) File "/usr/lib64/python3.7/http/client.py", line 1247, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) File "/usr/lib64/python3.7/http/client.py", line 1026, in _send_output self.send(msg) File "/usr/lib64/python3.7/http/client.py", line 966, in send self.connect() File "/usr/lib64/python3.7/http/client.py", line 1414, in connect super().connect() File "/usr/lib64/python3.7/http/client.py", line 938, in connect (self.host,self.port), self.timeout, self.source_address) File "/usr/lib64/python3.7/socket.py", line 727, in create_connection raise err File "/usr/lib64/python3.7/socket.py", line 716, in create_connection sock.connect(sa) OSError: [Errno 101] Network is unreachable During handling of the above exception, another exception occurred: 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

...

v2v/rhv-upload-plugin.py | 325 ++++++++++++++++++++++----------------- 1 file changed, 184 insertions(+), 141 deletions(-) -- 2.21.0 _______________________________________________ Libguestfs mailing list Libguestfs(a)redhat.com https://www.redhat.com/mailman/listinfo/libguestfs

Nir Soffer

3:35 a.m.

On Tue, Nov 19, 2019 at 11:16 AM Martin Kletzander <mkletzan(a)redhat.com> wrote:

...

On Mon, Nov 18, 2019 at 11:53:39PM +0200, Nir Soffer wrote: >This series extract oVirt SDK and imageio code to make it eaiser to follow the >code and improve error handing in open() and close(). > >Tested with virt-v2v master. > >Changes since v1: >- Rebase on merged patches from v1 >- Fix regression introduced by "rhv-upload: Fix cleanup after errors" >- Remove "rhv-upload: Try to remove disk on timeout" since it cannot > succeed >- Add more context in debug error logs >- Use disk_id instead of disk.id in close() > >v1 was here: >https://www.redhat.com/archives/libguestfs/2019-November/msg00060.html > >Nir Soffer (11): > rhv-upload: Cancel transfer if finalize failed > rhv-upload: Keep disk_id in handle > rhv-upload: Show disk id in error message > rhv-upload: Don't keep transfer_service in handle > rhv-upload: Get host before creating disk > rhv-upload: Extract create_transfer() function > rhv-upload: Show transfer id in error message > rhv-upload: Extract imageio helpers > rhv-upload: Extract get_options() helper > rhv-upload: Extract optimize_http() helper > rhv-upload: Clean up username and password > I'm not sure which one of these is causing it, it sounds like the first one, but basically the cleanup path is probably not checked well. I'm facing a completely different issue currently, but when updated to your version (in a hope that it might either provide more data in the error message or even fix it) I'm now getting a "During handling of the above exception, another exception occurred", which is not a good thing. I think it should be easy to fix and also check for similar issues elsewhere, but I'm now trying to figure out different things that bother me ('No route to host' changing to 'Network unreachable' after the patches even though I can connect everywhere the upload plugin is connecting), so I can't look at it right now. Here's the traceback: Traceback (most recent call last): File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 94, in open options = get_options(http, destination_url) File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 575, in get_options http.request("OPTIONS", url.path) File "/usr/lib64/python3.7/http/client.py", line 1252, in request self._send_request(method, url, body, headers, encode_chunked) File "/usr/lib64/python3.7/http/client.py", line 1298, in _send_request self.endheaders(body, encode_chunked=encode_chunked) File "/usr/lib64/python3.7/http/client.py", line 1247, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) File "/usr/lib64/python3.7/http/client.py", line 1026, in _send_output self.send(msg) File "/usr/lib64/python3.7/http/client.py", line 966, in send self.connect() File "/usr/lib64/python3.7/http/client.py", line 1414, in connect super().connect() File "/usr/lib64/python3.7/http/client.py", line 938, in connect (self.host,self.port), self.timeout, self.source_address) File "/usr/lib64/python3.7/socket.py", line 727, in create_connection raise err File "/usr/lib64/python3.7/socket.py", line 716, in create_connection sock.connect(sa) OSError: [Errno 101] Network is unreachable During handling of the above exception, another exception occurred: 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

transfer_service is indeed missing in open. Thanks for reporting it.

...

Nir Soffer

5:14 a.m.

On Tue, Nov 19, 2019 at 11:17 AM Martin Kletzander <mkletzan(a)redhat.com> wrote:

...

Does this fix the error for you? https://github.com/nirs/virt-v2v/commit/2f93dbffad81a26445831293ecac213ea... I did not test it yet.

...

> v2v/rhv-upload-plugin.py | 325 ++++++++++++++++++++++----------------- > 1 file changed, 184 insertions(+), 141 deletions(-) > >-- >2.21.0 > > >_______________________________________________ >Libguestfs mailing list >Libguestfs(a)redhat.com >https://www.redhat.com/mailman/listinfo/libguestfs _______________________________________________ Libguestfs mailing list Libguestfs(a)redhat.com https://www.redhat.com/mailman/listinfo/libguestfs

Martin Kletzander

6:16 a.m.

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(a)redhat.com> wrote: > > On Mon, Nov 18, 2019 at 11:53:39PM +0200, Nir Soffer wrote: > >This series extract oVirt SDK and imageio code to make it eaiser to follow the > >code and improve error handing in open() and close(). > > > >Tested with virt-v2v master. > > > >Changes since v1: > >- Rebase on merged patches from v1 > >- Fix regression introduced by "rhv-upload: Fix cleanup after errors" > >- Remove "rhv-upload: Try to remove disk on timeout" since it cannot > > succeed > >- Add more context in debug error logs > >- Use disk_id instead of disk.id in close() > > > >v1 was here: > >https://www.redhat.com/archives/libguestfs/2019-November/msg00060.html > > > >Nir Soffer (11): > > rhv-upload: Cancel transfer if finalize failed > > rhv-upload: Keep disk_id in handle > > rhv-upload: Show disk id in error message > > rhv-upload: Don't keep transfer_service in handle > > rhv-upload: Get host before creating disk > > rhv-upload: Extract create_transfer() function > > rhv-upload: Show transfer id in error message > > rhv-upload: Extract imageio helpers > > rhv-upload: Extract get_options() helper > > rhv-upload: Extract optimize_http() helper > > rhv-upload: Clean up username and password > > > > I'm not sure which one of these is causing it, it sounds like the first one, but > basically the cleanup path is probably not checked well. I'm facing a > completely different issue currently, but when updated to your version (in a > hope that it might either provide more data in the error message or even fix it) > I'm now getting a "During handling of the above exception, another exception > occurred", which is not a good thing. I think it should be easy to fix and also > check for similar issues elsewhere, but I'm now trying to figure out different > things that bother me ('No route to host' changing to 'Network unreachable' > after the patches even though I can connect everywhere the upload plugin is > connecting), so I can't look at it right now. Here's the traceback: > > Traceback (most recent call last): > File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 94, in open > options = get_options(http, destination_url) > File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 575, in get_options > http.request("OPTIONS", url.path) > File "/usr/lib64/python3.7/http/client.py", line 1252, in request > self._send_request(method, url, body, headers, encode_chunked) > File "/usr/lib64/python3.7/http/client.py", line 1298, in _send_request > self.endheaders(body, encode_chunked=encode_chunked) > File "/usr/lib64/python3.7/http/client.py", line 1247, in endheaders > self._send_output(message_body, encode_chunked=encode_chunked) > File "/usr/lib64/python3.7/http/client.py", line 1026, in _send_output > self.send(msg) > File "/usr/lib64/python3.7/http/client.py", line 966, in send > self.connect() > File "/usr/lib64/python3.7/http/client.py", line 1414, in connect > super().connect() > File "/usr/lib64/python3.7/http/client.py", line 938, in connect > (self.host,self.port), self.timeout, self.source_address) > File "/usr/lib64/python3.7/socket.py", line 727, in create_connection > raise err > File "/usr/lib64/python3.7/socket.py", line 716, in create_connection > sock.connect(sa) > OSError: [Errno 101] Network is unreachable > > During handling of the above exception, another exception occurred: > > 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/2f93dbffad81a26445831293ecac213ea... I did not test it yet.

If I remove the stray `def finalize_transfer(...)` it works, yes. 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.

...

> > > > v2v/rhv-upload-plugin.py | 325 ++++++++++++++++++++++----------------- > > 1 file changed, 184 insertions(+), 141 deletions(-) > > > >-- > >2.21.0 > > > > > >_______________________________________________ > >Libguestfs mailing list > >Libguestfs(a)redhat.com > >https://www.redhat.com/mailman/listinfo/libguestfs > _______________________________________________ > Libguestfs mailing list > Libguestfs(a)redhat.com > https://www.redhat.com/mailman/listinfo/libguestfs

Nir Soffer

6:24 a.m.

On Tue, Nov 19, 2019 at 2:16 PM Martin Kletzander <mkletzan(a)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(a)redhat.com> wrote: >> >> On Mon, Nov 18, 2019 at 11:53:39PM +0200, Nir Soffer wrote: >> >This series extract oVirt SDK and imageio code to make it eaiser to follow the >> >code and improve error handing in open() and close(). >> > >> >Tested with virt-v2v master. >> > >> >Changes since v1: >> >- Rebase on merged patches from v1 >> >- Fix regression introduced by "rhv-upload: Fix cleanup after errors" >> >- Remove "rhv-upload: Try to remove disk on timeout" since it cannot >> > succeed >> >- Add more context in debug error logs >> >- Use disk_id instead of disk.id in close() >> > >> >v1 was here: >> >https://www.redhat.com/archives/libguestfs/2019-November/msg00060.html >> > >> >Nir Soffer (11): >> > rhv-upload: Cancel transfer if finalize failed >> > rhv-upload: Keep disk_id in handle >> > rhv-upload: Show disk id in error message >> > rhv-upload: Don't keep transfer_service in handle >> > rhv-upload: Get host before creating disk >> > rhv-upload: Extract create_transfer() function >> > rhv-upload: Show transfer id in error message >> > rhv-upload: Extract imageio helpers >> > rhv-upload: Extract get_options() helper >> > rhv-upload: Extract optimize_http() helper >> > rhv-upload: Clean up username and password >> > >> >> I'm not sure which one of these is causing it, it sounds like the first one, but >> basically the cleanup path is probably not checked well. I'm facing a >> completely different issue currently, but when updated to your version (in a >> hope that it might either provide more data in the error message or even fix it) >> I'm now getting a "During handling of the above exception, another exception >> occurred", which is not a good thing. I think it should be easy to fix and also >> check for similar issues elsewhere, but I'm now trying to figure out different >> things that bother me ('No route to host' changing to 'Network unreachable' >> after the patches even though I can connect everywhere the upload plugin is >> connecting), so I can't look at it right now. Here's the traceback: >> >> Traceback (most recent call last): >> File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 94, in open >> options = get_options(http, destination_url) >> File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 575, in get_options >> http.request("OPTIONS", url.path) >> File "/usr/lib64/python3.7/http/client.py", line 1252, in request >> self._send_request(method, url, body, headers, encode_chunked) >> File "/usr/lib64/python3.7/http/client.py", line 1298, in _send_request >> self.endheaders(body, encode_chunked=encode_chunked) >> File "/usr/lib64/python3.7/http/client.py", line 1247, in endheaders >> self._send_output(message_body, encode_chunked=encode_chunked) >> File "/usr/lib64/python3.7/http/client.py", line 1026, in _send_output >> self.send(msg) >> File "/usr/lib64/python3.7/http/client.py", line 966, in send >> self.connect() >> File "/usr/lib64/python3.7/http/client.py", line 1414, in connect >> super().connect() >> File "/usr/lib64/python3.7/http/client.py", line 938, in connect >> (self.host,self.port), self.timeout, self.source_address) >> File "/usr/lib64/python3.7/socket.py", line 727, in create_connection >> raise err >> File "/usr/lib64/python3.7/socket.py", line 716, in create_connection >> sock.connect(sa) >> OSError: [Errno 101] Network is unreachable >> >> During handling of the above exception, another exception occurred: >> >> 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/2f93dbffad81a26445831293ecac213ea... > >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?

Martin Kletzander

6:48 a.m.

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(a)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(a)redhat.com> > wrote: > >> > >> On Mon, Nov 18, 2019 at 11:53:39PM +0200, Nir Soffer wrote: > >> >This series extract oVirt SDK and imageio code to make it eaiser to > follow the > >> >code and improve error handing in open() and close(). > >> > > >> >Tested with virt-v2v master. > >> > > >> >Changes since v1: > >> >- Rebase on merged patches from v1 > >> >- Fix regression introduced by "rhv-upload: Fix cleanup after errors" > >> >- Remove "rhv-upload: Try to remove disk on timeout" since it cannot > >> > succeed > >> >- Add more context in debug error logs > >> >- Use disk_id instead of disk.id in close() > >> > > >> >v1 was here: > >> >https://www.redhat.com/archives/libguestfs/2019-November/msg00060.html > >> > > >> >Nir Soffer (11): > >> > rhv-upload: Cancel transfer if finalize failed > >> > rhv-upload: Keep disk_id in handle > >> > rhv-upload: Show disk id in error message > >> > rhv-upload: Don't keep transfer_service in handle > >> > rhv-upload: Get host before creating disk > >> > rhv-upload: Extract create_transfer() function > >> > rhv-upload: Show transfer id in error message > >> > rhv-upload: Extract imageio helpers > >> > rhv-upload: Extract get_options() helper > >> > rhv-upload: Extract optimize_http() helper > >> > rhv-upload: Clean up username and password > >> > > >> > >> I'm not sure which one of these is causing it, it sounds like the first > one, but > >> basically the cleanup path is probably not checked well. I'm facing a > >> completely different issue currently, but when updated to your version > (in a > >> hope that it might either provide more data in the error message or > even fix it) > >> I'm now getting a "During handling of the above exception, another > exception > >> occurred", which is not a good thing. I think it should be easy to fix > and also > >> check for similar issues elsewhere, but I'm now trying to figure out > different > >> things that bother me ('No route to host' changing to 'Network > unreachable' > >> after the patches even though I can connect everywhere the upload > plugin is > >> connecting), so I can't look at it right now. Here's the traceback: > >> > >> Traceback (most recent call last): > >> File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 94, in > open > >> options = get_options(http, destination_url) > >> File "/var/tmp/rhvupload.Vw0CIU/rhv-upload-plugin.py", line 575, in > get_options > >> http.request("OPTIONS", url.path) > >> File "/usr/lib64/python3.7/http/client.py", line 1252, in request > >> self._send_request(method, url, body, headers, encode_chunked) > >> File "/usr/lib64/python3.7/http/client.py", line 1298, in > _send_request > >> self.endheaders(body, encode_chunked=encode_chunked) > >> File "/usr/lib64/python3.7/http/client.py", line 1247, in endheaders > >> self._send_output(message_body, encode_chunked=encode_chunked) > >> File "/usr/lib64/python3.7/http/client.py", line 1026, in _send_output > >> self.send(msg) > >> File "/usr/lib64/python3.7/http/client.py", line 966, in send > >> self.connect() > >> File "/usr/lib64/python3.7/http/client.py", line 1414, in connect > >> super().connect() > >> File "/usr/lib64/python3.7/http/client.py", line 938, in connect > >> (self.host,self.port), self.timeout, self.source_address) > >> File "/usr/lib64/python3.7/socket.py", line 727, in create_connection > >> raise err > >> File "/usr/lib64/python3.7/socket.py", line 716, in create_connection > >> sock.connect(sa) > >> OSError: [Errno 101] Network is unreachable > >> > >> During handling of the above exception, another exception occurred: > >> > >> 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/2f93dbffad81a26445831293ecac213ea... > > > >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.

Martin Kletzander

7:36 a.m.

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(a)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(a)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/2f93dbffad81a26445831293ecac213ea... >> > >> >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

Richard W.M. Jones

8:14 a.m.

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/b8b9dcc90dbd91aec4b6bb82dd511... 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/07806d6d5511bb5da2dfae2bf0009... 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

Martin Kletzander

8:24 a.m.

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/b8b9dcc90dbd91aec4b6bb82dd511... 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/07806d6d5511bb5da2dfae2bf0009... 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

Nir Soffer

8:14 a.m.

On Tue, Nov 19, 2019 at 3:36 PM Martin Kletzander <mkletzan(a)redhat.com> wrote:

...

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.

...

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?

Martin Kletzander

8:29 a.m.

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(a)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(a)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(a)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/2f93dbffad81a26445831293ecac213ea... > >>> > > >>> >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 =)

Nir Soffer

10:16 a.m.

On Tue, Nov 19, 2019 at 4:34 PM Martin Kletzander <mkletzan(a)redhat.com> wrote:

...

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(a)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(a)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(a)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/2f93dbffad81a26445831293ecac213ea... >> >>> > >> >>> >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.

Can you share entire virt-v2v log, and /var/log/ovirt-imageio-daemon/daemon.log from the host you are uploading to? if you use the proxy (transfer.proxy_url), which you should not, also the proxy log from the engine host (/var/log/ovirt-imageio-proxy/image-proxy.log).

Martin Kletzander

Wednesday, 20 November Wed, 20 Nov

7:46 a.m.

On Tue, Nov 19, 2019 at 06:16:57PM +0200, Nir Soffer wrote:

...

On Tue, Nov 19, 2019 at 4:34 PM Martin Kletzander <mkletzan(a)redhat.com> wrote: >On Tue, Nov 19, 2019 at 04:14:45PM +0200, Nir Soffer wrote: >>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. Can you share entire virt-v2v log, and /var/log/ovirt-imageio-daemon/daemon.log from the host you are uploading to? if you use the proxy (transfer.proxy_url), which you should not, also the proxy log from the engine host (/var/log/ovirt-imageio-proxy/image-proxy.log).

I'll follow up personally as this is probably not related to anyone on this list and I feel like spamming everyone.

Martin Kletzander

Tuesday, 19 November Tue, 19 Nov

8:20 a.m.

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(a)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(a)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/2f93dbffad81a26445831293ecac213ea... >>> > >>> >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

1860

days inactive

1862

days old

guestfs@lists.libguestfs.org

Manage subscription

26 comments

4 participants

tags (0)

participants (4)

Martin Kletzander
Nir Soffer
Nir Soffer
Richard W.M. Jones

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

[PATCH v2 00/11] rvh-upload: Various fixes and cleanups