[PATCH] -o rhv-upload: wait for VM creation task
oVirt API call for VM creation finishes before the VM is actually created. Entities may be still locked after virt-v2v terminates and if user tries to perform (scripted) actions after virt-v2v those operations may fail. To prevent this it is useful to monitor the task and wait for the completion. This will also help to prevent some corner case scenarios (that would be difficult to debug) when the VM creation job fails after virt-v2v already termintates with success. Thanks: Nir Soffer Signed-off-by: Tomáš Golembiovský <tgolembi@redhat.com> Reviewed-by: Arik Hadas <ahadas@redhat.com> --- output/rhv-upload-createvm.py | 57 ++++++++++++++++++++++++++++++++++- 1 file changed, 56 insertions(+), 1 deletion(-) diff --git a/output/rhv-upload-createvm.py b/output/rhv-upload-createvm.py index 50bb7e34..c6a6fbd6 100644 --- a/output/rhv-upload-createvm.py +++ b/output/rhv-upload-createvm.py @@ -19,12 +19,54 @@ import json import logging import sys +import time +import uuid from urllib.parse import urlparse import ovirtsdk4 as sdk import ovirtsdk4.types as types + +def debug(s): + if params['verbose']: + print(s, file=sys.stderr) + sys.stderr.flush() + + +def jobs_completed(system_service, correlation_id): + jobs_service = system_service.jobs_service() + + try: + jobs = jobs_service.list( + search="correlation_id=%s" % correlation_id) + except sdk.Error as e: + debug( + "Error searching for jobs with correlation id %s: %s" % + (correlation_id, e)) + # We dont know, assume that jobs did not complete yet. + return False + + # STARTED is the only "in progress" status, other mean the job has + # already terminated + if all(job.status != types.JobStatus.STARTED for job in jobs): + failed_jobs = [(job.description, str(job.status)) + for job in jobs + if job.status != types.JobStatus.FINISHED] + if failed_jobs: + raise RuntimeError( + "Failed to create a VM! Failed jobs: %r" % failed_jobs) + return True + else: + jobs_status = [(job.description, str(job.status)) for job in jobs] + debug("Some jobs with correlation id %s are running: %s" % + (correlation_id, jobs_status)) + return False + + +# Seconds to wait for the VM import job to complete in oVirt. +timeout = 5 * 60 + # Parameters are passed in via a JSON doc from the OCaml code. # Because this Python code ships embedded inside virt-v2v there # is no formal API here. @@ -67,6 +109,7 @@ system_service = connection.system_service() cluster = system_service.clusters_service().cluster_service(params['rhv_cluster_uuid']) cluster = cluster.get() +correlation_id = str(uuid.uuid4()) vms_service = system_service.vms_service() vm = vms_service.add( types.Vm( @@ -77,5 +120,17 @@ vm = vms_service.add( data=ovf, ) ) - ) + ), + query={'correlation_id': correlation_id}, ) + +# Wait for the import job to finish +endt = time.time() + timeout +while True: + time.sleep(1) + if jobs_completed(system_service, correlation_id): + break + if time.time() > endt: + raise RuntimeError( + "Timed out waiting for VM creation!" + " Jobs still running for correlation id %s" % correlation_id) -- 2.35.1
On Tue, Apr 12, 2022 at 08:34:27PM +0200, Tomáš Golembiovský wrote:
oVirt API call for VM creation finishes before the VM is actually created. Entities may be still locked after virt-v2v terminates and if user tries to perform (scripted) actions after virt-v2v those operations may fail. To prevent this it is useful to monitor the task and wait for the completion. This will also help to prevent some corner case scenarios (that would be difficult to debug) when the VM creation job fails after virt-v2v already termintates with success.
Forgot to mention this is related to bug: https://bugzilla.redhat.com/show_bug.cgi?id=1985827
Thanks: Nir Soffer Signed-off-by: Tomáš Golembiovský <tgolembi@redhat.com> Reviewed-by: Arik Hadas <ahadas@redhat.com> --- output/rhv-upload-createvm.py | 57 ++++++++++++++++++++++++++++++++++- 1 file changed, 56 insertions(+), 1 deletion(-)
-- Tomáš Golembiovský <tgolembi@redhat.com>
On Tue, Apr 12, 2022 at 08:34:27PM +0200, Tomáš Golembiovský wrote:
oVirt API call for VM creation finishes before the VM is actually created. Entities may be still locked after virt-v2v terminates and if user tries to perform (scripted) actions after virt-v2v those operations may fail. To prevent this it is useful to monitor the task and wait for the completion. This will also help to prevent some corner case scenarios (that would be difficult to debug) when the VM creation job fails after virt-v2v already termintates with success.
Thanks: Nir Soffer Signed-off-by: Tomáš Golembiovský <tgolembi@redhat.com> Reviewed-by: Arik Hadas <ahadas@redhat.com>
It breaks this test: FAIL: output/test-v2v-python-syntax.sh ./rhv-upload-createvm.py:63:19: E127 continuation line over-indented for visual indent Looking at the code this seems like a possible false alarm, but we do need to have the test passing, so please check this. It also breaks: FAIL: tests/test-v2v-o-rhv-upload.sh I suspect that the internal test harness needs to be extended to add this new API (jobs_service?) Don't forget to put "Fixes: https://bugzilla..." in the description. Rich.
output/rhv-upload-createvm.py | 57 ++++++++++++++++++++++++++++++++++- 1 file changed, 56 insertions(+), 1 deletion(-)
diff --git a/output/rhv-upload-createvm.py b/output/rhv-upload-createvm.py index 50bb7e34..c6a6fbd6 100644 --- a/output/rhv-upload-createvm.py +++ b/output/rhv-upload-createvm.py @@ -19,12 +19,54 @@ import json import logging import sys +import time +import uuid
from urllib.parse import urlparse
import ovirtsdk4 as sdk import ovirtsdk4.types as types
+ +def debug(s): + if params['verbose']: + print(s, file=sys.stderr) + sys.stderr.flush() + + +def jobs_completed(system_service, correlation_id): + jobs_service = system_service.jobs_service() + + try: + jobs = jobs_service.list( + search="correlation_id=%s" % correlation_id) + except sdk.Error as e: + debug( + "Error searching for jobs with correlation id %s: %s" % + (correlation_id, e)) + # We dont know, assume that jobs did not complete yet. + return False + + # STARTED is the only "in progress" status, other mean the job has + # already terminated + if all(job.status != types.JobStatus.STARTED for job in jobs): + failed_jobs = [(job.description, str(job.status)) + for job in jobs + if job.status != types.JobStatus.FINISHED] + if failed_jobs: + raise RuntimeError( + "Failed to create a VM! Failed jobs: %r" % failed_jobs) + return True + else: + jobs_status = [(job.description, str(job.status)) for job in jobs] + debug("Some jobs with correlation id %s are running: %s" % + (correlation_id, jobs_status)) + return False + + +# Seconds to wait for the VM import job to complete in oVirt. +timeout = 5 * 60 + # Parameters are passed in via a JSON doc from the OCaml code. # Because this Python code ships embedded inside virt-v2v there # is no formal API here. @@ -67,6 +109,7 @@ system_service = connection.system_service() cluster = system_service.clusters_service().cluster_service(params['rhv_cluster_uuid']) cluster = cluster.get()
+correlation_id = str(uuid.uuid4()) vms_service = system_service.vms_service() vm = vms_service.add( types.Vm( @@ -77,5 +120,17 @@ vm = vms_service.add( data=ovf, ) ) - ) + ), + query={'correlation_id': correlation_id}, ) + +# Wait for the import job to finish +endt = time.time() + timeout +while True: + time.sleep(1) + if jobs_completed(system_service, correlation_id): + break + if time.time() > endt: + raise RuntimeError( + "Timed out waiting for VM creation!" + " Jobs still running for correlation id %s" % correlation_id) -- 2.35.1
_______________________________________________ Libguestfs mailing list Libguestfs@redhat.com https://listman.redhat.com/mailman/listinfo/libguestfs
-- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-top is 'top' for virtual machines. Tiny program with many powerful monitoring features, net stats, disk stats, logging, etc. http://people.redhat.com/~rjones/virt-top
On Tue, Apr 12, 2022 at 9:35 PM Tomáš Golembiovský <tgolembi@redhat.com> wrote:
oVirt API call for VM creation finishes before the VM is actually created. Entities may be still locked after virt-v2v terminates and if user tries to perform (scripted) actions after virt-v2v those operations may fail. To prevent this it is useful to monitor the task and wait for the completion. This will also help to prevent some corner case scenarios (that would be difficult to debug) when the VM creation job fails after virt-v2v already termintates with success.
Thanks: Nir Soffer Signed-off-by: Tomáš Golembiovský <tgolembi@redhat.com> Reviewed-by: Arik Hadas <ahadas@redhat.com> --- output/rhv-upload-createvm.py | 57 ++++++++++++++++++++++++++++++++++- 1 file changed, 56 insertions(+), 1 deletion(-)
diff --git a/output/rhv-upload-createvm.py b/output/rhv-upload-createvm.py index 50bb7e34..c6a6fbd6 100644 --- a/output/rhv-upload-createvm.py +++ b/output/rhv-upload-createvm.py @@ -19,12 +19,54 @@ import json import logging import sys +import time +import uuid
from urllib.parse import urlparse
import ovirtsdk4 as sdk import ovirtsdk4.types as types
+ +def debug(s): + if params['verbose']: + print(s, file=sys.stderr) + sys.stderr.flush() + + +def jobs_completed(system_service, correlation_id): + jobs_service = system_service.jobs_service() + + try: + jobs = jobs_service.list( + search="correlation_id=%s" % correlation_id) + except sdk.Error as e: + debug( + "Error searching for jobs with correlation id %s: %s" % + (correlation_id, e)) + # We dont know, assume that jobs did not complete yet.
don't?
+ return False + + # STARTED is the only "in progress" status, other mean the job has
"other" -> "anything else"?
+ # already terminated
Missing . at the end of the comment.
+ if all(job.status != types.JobStatus.STARTED for job in jobs): + failed_jobs = [(job.description, str(job.status)) + for job in jobs + if job.status != types.JobStatus.FINISHED] + if failed_jobs: + raise RuntimeError( + "Failed to create a VM! Failed jobs: %r" % failed_jobs) + return True + else: + jobs_status = [(job.description, str(job.status)) for job in jobs]
jobs_status is a little confusing since this is a list of (description, status) tuples. Maybe "running_jobs"? It is also more consistent with "failed_jobs" above.
+ debug("Some jobs with correlation id %s are running: %s" % + (correlation_id, jobs_status)) + return False + + +# Seconds to wait for the VM import job to complete in oVirt. +timeout = 5 * 60 + # Parameters are passed in via a JSON doc from the OCaml code. # Because this Python code ships embedded inside virt-v2v there # is no formal API here. @@ -67,6 +109,7 @@ system_service = connection.system_service() cluster = system_service.clusters_service().cluster_service(params['rhv_cluster_uuid']) cluster = cluster.get()
+correlation_id = str(uuid.uuid4()) vms_service = system_service.vms_service() vm = vms_service.add( types.Vm( @@ -77,5 +120,17 @@ vm = vms_service.add( data=ovf, ) ) - ) + ), + query={'correlation_id': correlation_id}, ) + +# Wait for the import job to finish +endt = time.time() + timeout
Since we use python 3, it is better to use time.monotonic() which is affected by system time changes.
+while True: + time.sleep(1)
Since we wait up to 300 seconds, maybe use a longer delay? Or maybe we don't need to wait for 300 seconds?
+ if jobs_completed(system_service, correlation_id): + break + if time.time() > endt: + raise RuntimeError( + "Timed out waiting for VM creation!" + " Jobs still running for correlation id %s" % correlation_id) -- 2.35.1
_______________________________________________ Libguestfs mailing list Libguestfs@redhat.com https://listman.redhat.com/mailman/listinfo/libguestfs
With or without suggested minor improvements, Reviewed-by: Nir Soffer <nsoffer@redhat.com> Nir
On Wed, Apr 13, 2022 at 09:32:14PM +0300, Nir Soffer wrote:
+# Wait for the import job to finish +endt = time.time() + timeout
Since we use python 3, it is better to use time.monotonic() which is affected by system time changes.
Interesting - we use time.time() quite a lot at the moment. How about the following patch? It passes tests for me locally (so only against the test harness, not real RHV). Rich. diff --git a/output/rhv-upload-finalize.py b/output/rhv-upload-finalize.py index 4d1dcfb2f4..1221e766ac 100644 --- a/output/rhv-upload-finalize.py +++ b/output/rhv-upload-finalize.py @@ -73,7 +73,7 @@ def finalize_transfer(connection, transfer_id, disk_id): .image_transfers_service() .image_transfer_service(transfer_id)) - start = time.time() + start = time.monotonic() transfer_service.finalize() @@ -125,14 +125,14 @@ def finalize_transfer(connection, transfer_id, disk_id): raise RuntimeError( "transfer %s was paused by system" % (transfer.id,)) - if time.time() > start + timeout: + if time.monotonic() > start + timeout: raise RuntimeError( "timed out waiting for transfer %s to finalize, " "transfer is %s" % (transfer.id, transfer.phase)) debug("transfer %s finalized in %.3f seconds" - % (transfer_id, time.time() - start)) + % (transfer_id, time.monotonic() - start)) # Parameters are passed in via a JSON doc from the OCaml code. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com libguestfs lets you edit virtual machines. Supports shell scripting, bindings from many languages. http://libguestfs.org
Sorry, that patch was incomplete. Here's a better patch. Rich. commit d2c018676111de0d5fb895301fb9035c8763f5bb (HEAD -> master) Author: Richard W.M. Jones <rjones@redhat.com> Date: Thu Apr 14 09:09:15 2022 +0100 -o rhv-upload: Use time.monotonic In Python >= 3.3 we can use a monotonic instead of system clock, which ensures the clock will never go backwards during these loops. Thanks: Nir Soffer diff --git a/output/rhv-upload-finalize.py b/output/rhv-upload-finalize.py index 4d1dcfb2f4..1221e766ac 100644 --- a/output/rhv-upload-finalize.py +++ b/output/rhv-upload-finalize.py @@ -73,7 +73,7 @@ def finalize_transfer(connection, transfer_id, disk_id): .image_transfers_service() .image_transfer_service(transfer_id)) - start = time.time() + start = time.monotonic() transfer_service.finalize() @@ -125,14 +125,14 @@ def finalize_transfer(connection, transfer_id, disk_id): raise RuntimeError( "transfer %s was paused by system" % (transfer.id,)) - if time.time() > start + timeout: + if time.monotonic() > start + timeout: raise RuntimeError( "timed out waiting for transfer %s to finalize, " "transfer is %s" % (transfer.id, transfer.phase)) debug("transfer %s finalized in %.3f seconds" - % (transfer_id, time.time() - start)) + % (transfer_id, time.monotonic() - start)) # Parameters are passed in via a JSON doc from the OCaml code. diff --git a/output/rhv-upload-transfer.py b/output/rhv-upload-transfer.py index cf4f8807e6..62b842b67b 100644 --- a/output/rhv-upload-transfer.py +++ b/output/rhv-upload-transfer.py @@ -128,13 +128,13 @@ def create_disk(connection): # can't start if the disk is locked. disk_service = disks_service.disk_service(disk.id) - endt = time.time() + timeout + endt = time.monotonic() + timeout while True: time.sleep(1) disk = disk_service.get() if disk.status == types.DiskStatus.OK: break - if time.time() > endt: + if time.monotonic() > endt: raise RuntimeError( "timed out waiting for disk %s to become unlocked" % disk.id) @@ -176,7 +176,7 @@ def create_transfer(connection, disk, host): # If the transfer was paused, we need to cancel it to remove the disk, # otherwise the system will remove the disk and transfer shortly after. - endt = time.time() + timeout + endt = time.monotonic() + timeout while True: time.sleep(1) try: @@ -204,7 +204,7 @@ def create_transfer(connection, disk, host): "unexpected transfer %s phase %s" % (transfer.id, transfer.phase)) - if time.time() > endt: + if time.monotonic() > endt: transfer_service.cancel() raise RuntimeError( "timed out waiting for transfer %s" % transfer.id) -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-top is 'top' for virtual machines. Tiny program with many powerful monitoring features, net stats, disk stats, logging, etc. http://people.redhat.com/~rjones/virt-top
On Thu, Apr 14, 2022 at 11:11 AM Richard W.M. Jones <rjones@redhat.com> wrote:
Sorry, that patch was incomplete. Here's a better patch.
Rich.
commit d2c018676111de0d5fb895301fb9035c8763f5bb (HEAD -> master) Author: Richard W.M. Jones <rjones@redhat.com> Date: Thu Apr 14 09:09:15 2022 +0100
-o rhv-upload: Use time.monotonic
In Python >= 3.3 we can use a monotonic instead of system clock, which ensures the clock will never go backwards during these loops.
Thanks: Nir Soffer
diff --git a/output/rhv-upload-finalize.py b/output/rhv-upload-finalize.py index 4d1dcfb2f4..1221e766ac 100644 --- a/output/rhv-upload-finalize.py +++ b/output/rhv-upload-finalize.py @@ -73,7 +73,7 @@ def finalize_transfer(connection, transfer_id, disk_id): .image_transfers_service() .image_transfer_service(transfer_id))
- start = time.time() + start = time.monotonic()
transfer_service.finalize()
@@ -125,14 +125,14 @@ def finalize_transfer(connection, transfer_id, disk_id): raise RuntimeError( "transfer %s was paused by system" % (transfer.id,))
- if time.time() > start + timeout: + if time.monotonic() > start + timeout: raise RuntimeError( "timed out waiting for transfer %s to finalize, " "transfer is %s" % (transfer.id, transfer.phase))
debug("transfer %s finalized in %.3f seconds" - % (transfer_id, time.time() - start)) + % (transfer_id, time.monotonic() - start))
# Parameters are passed in via a JSON doc from the OCaml code. diff --git a/output/rhv-upload-transfer.py b/output/rhv-upload-transfer.py index cf4f8807e6..62b842b67b 100644 --- a/output/rhv-upload-transfer.py +++ b/output/rhv-upload-transfer.py @@ -128,13 +128,13 @@ def create_disk(connection): # can't start if the disk is locked.
disk_service = disks_service.disk_service(disk.id) - endt = time.time() + timeout + endt = time.monotonic() + timeout while True: time.sleep(1) disk = disk_service.get() if disk.status == types.DiskStatus.OK: break - if time.time() > endt: + if time.monotonic() > endt: raise RuntimeError( "timed out waiting for disk %s to become unlocked" % disk.id)
@@ -176,7 +176,7 @@ def create_transfer(connection, disk, host): # If the transfer was paused, we need to cancel it to remove the disk, # otherwise the system will remove the disk and transfer shortly after.
- endt = time.time() + timeout + endt = time.monotonic() + timeout while True: time.sleep(1) try: @@ -204,7 +204,7 @@ def create_transfer(connection, disk, host): "unexpected transfer %s phase %s" % (transfer.id, transfer.phase))
- if time.time() > endt: + if time.monotonic() > endt: transfer_service.cancel() raise RuntimeError( "timed out waiting for transfer %s" % transfer.id)
Looks good. Nir
participants (3)
-
Nir Soffer -
Richard W.M. Jones -
Tomáš Golembiovský