From 515f76aa918b3345044437cab9c661ec83d4602c Mon Sep 17 00:00:00 2001 From: Ivan Ivanov Date: Mon, 15 May 2023 14:31:10 +0300 Subject: [PATCH 1/6] Correctly calculate `Job.started_at`/`Job.finished_at` Since before_docker_run/after_docker_run were called respenctively before/after setting the status and started_at/finished_at, it was causing timing issues in tests and not only. --- .../migrations/0067_auto_20230515_1320.py | 23 +++++++++++++++++++ docker-app/qfieldcloud/core/models.py | 2 ++ docker-app/worker_wrapper/wrapper.py | 19 +++++++++++---- 3 files changed, 39 insertions(+), 5 deletions(-) create mode 100755 docker-app/qfieldcloud/core/migrations/0067_auto_20230515_1320.py diff --git a/docker-app/qfieldcloud/core/migrations/0067_auto_20230515_1320.py b/docker-app/qfieldcloud/core/migrations/0067_auto_20230515_1320.py new file mode 100755 index 000000000..dc6966d2d --- /dev/null +++ b/docker-app/qfieldcloud/core/migrations/0067_auto_20230515_1320.py @@ -0,0 +1,23 @@ +# Generated by Django 3.2.18 on 2023-05-15 11:20 + +from django.db import migrations, models + + +class Migration(migrations.Migration): + + dependencies = [ + ("core", "0066_delta_client_id"), + ] + + operations = [ + migrations.AddField( + model_name="job", + name="docker_finished_at", + field=models.DateTimeField(blank=True, editable=False, null=True), + ), + migrations.AddField( + model_name="job", + name="docker_started_at", + field=models.DateTimeField(blank=True, editable=False, null=True), + ), + ] diff --git a/docker-app/qfieldcloud/core/models.py b/docker-app/qfieldcloud/core/models.py index c384d03de..d382ef542 100644 --- a/docker-app/qfieldcloud/core/models.py +++ b/docker-app/qfieldcloud/core/models.py @@ -1536,6 +1536,8 @@ class Status(models.TextChoices): updated_at = models.DateTimeField(auto_now=True, db_index=True) started_at = models.DateTimeField(blank=True, null=True, editable=False) finished_at = models.DateTimeField(blank=True, null=True, editable=False) + docker_started_at = models.DateTimeField(blank=True, null=True, editable=False) + docker_finished_at = models.DateTimeField(blank=True, null=True, editable=False) @property def short_id(self) -> str: diff --git a/docker-app/worker_wrapper/wrapper.py b/docker-app/worker_wrapper/wrapper.py index e7386a740..184f9c9af 100644 --- a/docker-app/worker_wrapper/wrapper.py +++ b/docker-app/worker_wrapper/wrapper.py @@ -106,12 +106,12 @@ def run(self): feedback = {} try: - self.before_docker_run() - self.job.status = Job.Status.STARTED self.job.started_at = timezone.now() self.job.save() + self.before_docker_run() + command = self.get_command() volumes = [] volumes.append(f"{str(self.shared_tempdir)}:/io/:rw") @@ -147,7 +147,7 @@ def run(self): self.job.output = output.decode("utf-8") self.job.feedback = feedback - self.job.finished_at = timezone.now() + self.job.save() if exit_code != 0 or feedback.get("error") is not None: self.job.status = Job.Status.FAILED @@ -166,11 +166,12 @@ def run(self): # make sure we have reloaded the project, since someone might have changed it already self.job.project.refresh_from_db() + self.after_docker_run() + + self.job.finished_at = timezone.now() self.job.status = Job.Status.FINISHED self.job.save() - self.after_docker_run() - except Exception as err: (_type, _value, tb) = sys.exc_info() feedback["error"] = str(err) @@ -241,6 +242,10 @@ def _run_docker( logger.info(f"Execute: {' '.join(command)}") volumes.append(f"{TRANSFORMATION_GRIDS_VOLUME_NAME}:/transformation_grids:ro") + # `docker_started_at`/`docker_finished_at` tracks the time spent on docker only + self.job.docker_started_at = timezone.now() + self.job.save() + container: Container = client.containers.run( # type:ignore QGIS_CONTAINER_NAME, command, @@ -271,6 +276,10 @@ def _run_docker( except Exception as err: logger.exception("Timeout error.", exc_info=err) + # `docker_started_at`/`docker_finished_at` tracks the time spent on docker only + self.job.docker_finished_at = timezone.now() + self.job.save() + logs = b"" # Retry reading the logs, as it may fail # NOTE when reading the logs of a finished container, it might timeout with an ``. From 8570e8252ce21e7171a60d356897c2be49f546ae Mon Sep 17 00:00:00 2001 From: faebebin Date: Mon, 15 May 2023 17:32:28 +0200 Subject: [PATCH 2/6] remove unnecessary check --- docker-app/worker_wrapper/wrapper.py | 68 ++++++++++++++-------------- 1 file changed, 33 insertions(+), 35 deletions(-) diff --git a/docker-app/worker_wrapper/wrapper.py b/docker-app/worker_wrapper/wrapper.py index 184f9c9af..94117db98 100644 --- a/docker-app/worker_wrapper/wrapper.py +++ b/docker-app/worker_wrapper/wrapper.py @@ -323,46 +323,44 @@ def before_docker_run(self) -> None: self.data_last_packaged_at = timezone.now() def after_docker_run(self) -> None: - # only successfully finished packaging jobs should update the Project.data_last_packaged_at - if self.job.status == Job.Status.FINISHED: - self.job.project.data_last_packaged_at = self.data_last_packaged_at - self.job.project.last_package_job = self.job - self.job.project.save( - update_fields=( - "data_last_packaged_at", - "last_package_job", - ) + self.job.project.data_last_packaged_at = self.data_last_packaged_at + self.job.project.last_package_job = self.job + self.job.project.save( + update_fields=( + "data_last_packaged_at", + "last_package_job", ) + ) - try: - project_id = str(self.job.project.id) - package_ids = storage.get_stored_package_ids(project_id) - job_ids = [ - str(job["id"]) - for job in Job.objects.filter( - type=Job.Type.PACKAGE, - ) - .exclude( - status__in=(Job.Status.FAILED, Job.Status.FINISHED), - ) - .values("id") - ] + try: + project_id = str(self.job.project.id) + package_ids = storage.get_stored_package_ids(project_id) + job_ids = [ + str(job["id"]) + for job in Job.objects.filter( + type=Job.Type.PACKAGE, + ) + .exclude( + status__in=(Job.Status.FAILED, Job.Status.FINISHED), + ) + .values("id") + ] - for package_id in package_ids: - # keep the last package - if package_id == str(self.job.project.last_package_job_id): - continue + for package_id in package_ids: + # keep the last package + if package_id == str(self.job.project.last_package_job_id): + continue - # the job is still active, so it might be one of the new packages - if package_id in job_ids: - continue + # the job is still active, so it might be one of the new packages + if package_id in job_ids: + continue - storage.delete_stored_package(project_id, package_id) - except Exception as err: - logger.error( - "Failed to delete dangling packages, will be deleted via CRON later.", - exc_info=err, - ) + storage.delete_stored_package(project_id, package_id) + except Exception as err: + logger.error( + "Failed to delete dangling packages, will be deleted via CRON later.", + exc_info=err, + ) class DeltaApplyJobRun(JobRun): From d62006a79fb36b330381562d9eb81a0dc7f6cf97 Mon Sep 17 00:00:00 2001 From: faebebin Date: Mon, 15 May 2023 18:05:05 +0200 Subject: [PATCH 3/6] fix PackageJobRun.after_docker_run --- docker-app/worker_wrapper/wrapper.py | 1 + 1 file changed, 1 insertion(+) diff --git a/docker-app/worker_wrapper/wrapper.py b/docker-app/worker_wrapper/wrapper.py index 94117db98..e2e18ff9f 100644 --- a/docker-app/worker_wrapper/wrapper.py +++ b/docker-app/worker_wrapper/wrapper.py @@ -340,6 +340,7 @@ def after_docker_run(self) -> None: for job in Job.objects.filter( type=Job.Type.PACKAGE, ) + .exclude(id=self.job_id) .exclude( status__in=(Job.Status.FAILED, Job.Status.FINISHED), ) From 0104c2ca2dae224d92b0dcf70f73dea7829d7968 Mon Sep 17 00:00:00 2001 From: faebebin Date: Tue, 16 May 2023 08:40:01 +0200 Subject: [PATCH 4/6] Add another refresh_from_db to stabilize local tests --- docker-app/qfieldcloud/core/tests/test_packages.py | 1 + docker-app/worker_wrapper/wrapper.py | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/docker-app/qfieldcloud/core/tests/test_packages.py b/docker-app/qfieldcloud/core/tests/test_packages.py index 880fa20bb..bcc27bbeb 100644 --- a/docker-app/qfieldcloud/core/tests/test_packages.py +++ b/docker-app/qfieldcloud/core/tests/test_packages.py @@ -170,6 +170,7 @@ def check_package( payload = response.json() if payload["status"] == Job.Status.FINISHED: + project.refresh_from_db() response = self.client.get(f"/api/v1/packages/{project.id}/latest/") package_payload = response.json() diff --git a/docker-app/worker_wrapper/wrapper.py b/docker-app/worker_wrapper/wrapper.py index e2e18ff9f..dcb1b4aff 100644 --- a/docker-app/worker_wrapper/wrapper.py +++ b/docker-app/worker_wrapper/wrapper.py @@ -340,7 +340,7 @@ def after_docker_run(self) -> None: for job in Job.objects.filter( type=Job.Type.PACKAGE, ) - .exclude(id=self.job_id) + .exclude(id=self.job.id) .exclude( status__in=(Job.Status.FAILED, Job.Status.FINISHED), ) From d03a1f3aee4f99d99aee1e85dd1b4ae5466446b3 Mon Sep 17 00:00:00 2001 From: faebebin Date: Tue, 16 May 2023 08:41:43 +0200 Subject: [PATCH 5/6] Add back the comment --- docker-app/worker_wrapper/wrapper.py | 1 + 1 file changed, 1 insertion(+) diff --git a/docker-app/worker_wrapper/wrapper.py b/docker-app/worker_wrapper/wrapper.py index dcb1b4aff..493016abe 100644 --- a/docker-app/worker_wrapper/wrapper.py +++ b/docker-app/worker_wrapper/wrapper.py @@ -323,6 +323,7 @@ def before_docker_run(self) -> None: self.data_last_packaged_at = timezone.now() def after_docker_run(self) -> None: + # only successfully finished packaging jobs should update the Project.data_last_packaged_at self.job.project.data_last_packaged_at = self.data_last_packaged_at self.job.project.last_package_job = self.job self.job.project.save( From 03b7e96d63f25b525fcb595d30f84e9815b990a3 Mon Sep 17 00:00:00 2001 From: faebebin Date: Tue, 16 May 2023 08:43:16 +0200 Subject: [PATCH 6/6] format --- docker-app/worker_wrapper/wrapper.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docker-app/worker_wrapper/wrapper.py b/docker-app/worker_wrapper/wrapper.py index 493016abe..c0f0325a0 100644 --- a/docker-app/worker_wrapper/wrapper.py +++ b/docker-app/worker_wrapper/wrapper.py @@ -323,7 +323,7 @@ def before_docker_run(self) -> None: self.data_last_packaged_at = timezone.now() def after_docker_run(self) -> None: - # only successfully finished packaging jobs should update the Project.data_last_packaged_at + # only successfully finished packaging jobs should update the Project.data_last_packaged_at self.job.project.data_last_packaged_at = self.data_last_packaged_at self.job.project.last_package_job = self.job self.job.project.save(