Correctly calculate Job.started_at/Job.finished_at

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),
+        ),
+    ]

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:

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 ``.
@@ -314,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):