Add logs for inspecting celery queue delays

Using CoprBuildEndHandler as measuring task

Author: majamassarini

packit_service/worker/handlers/copr.py

@@ -301,6 +301,12 @@ def set_built_packages(self):
 
     def run(self):
         run_start_time = datetime.now(timezone.utc)
+        logger.info(
+            f"[CELERY_EXEC] CoprBuildEndHandler execution started for "
+            f"build_id={self.copr_event.build_id} "
+            f"chroot={self.copr_event.chroot} "
+            f"at {run_start_time.isoformat()}"
+        )
         if not self.build:
             # TODO: how could this happen?
             model = "SRPMBuildDB" if self.copr_event.chroot == COPR_SRPM_CHROOT else "CoprBuildDB"

packit_service/worker/helpers/build/babysit.py

@@ -57,6 +57,18 @@
 
 def celery_run_async(signatures: list[Signature]) -> None:
     logger.debug("Signatures are going to be sent to Celery (from babysit task).")
+    # Extract build_id from signatures for tracking
+    build_ids = [
+        str(build_id)
+        for sig in signatures
+        if sig.kwargs and (build_id := sig.kwargs.get("event", {}).get("build_id"))
+    ]
+    build_ids_str = ", ".join(build_ids) if build_ids else "unknown"
+    queued_time = datetime.now(timezone.utc)
+    logger.info(
+        f"[CELERY_QUEUE] Queuing {len(signatures)} task(s) for Copr build(s) {build_ids_str} "
+        f"at {queued_time.isoformat()}"
+    )
     # https://docs.celeryq.dev/en/stable/userguide/canvas.html#groups
     celery.group(signatures).apply_async()
     logger.debug("Signatures were sent to Celery.")