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.

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 ``.