Merge branch 'main' into rebase/forgejo

Author: mynk8

packit_service/worker/handlers/copr.py

@@ -139,6 +139,15 @@ def get_checkers() -> tuple[type[Checker], ...]:
         return (AreOwnerAndProjectMatchingJob, IsPackageMatchingJobView)
 
 
+def report_long_runtime(method: str, length: int, start_time: datetime):
+    end_time = datetime.now(timezone.utc)
+    run_time = elapsed_seconds(start_time, end_time)
+    if run_time > length:
+        m = f"{method} run time takes {run_time} seconds."
+        logger.info(m)
+        sentry_integration.send_to_sentry(RuntimeWarning(m))
+
+
 @configured_as(job_type=JobType.copr_build)
 @reacts_to(event=copr.Start)
 class CoprBuildStartHandler(AbstractCoprBuildReportHandler):
@@ -165,6 +174,7 @@ def set_logs_url(self):
         self.build.set_build_logs_url(copr_build_logs)
 
     def run(self):
+        run_start_time = datetime.now(timezone.utc)
         if not self.build:
             model = "SRPMBuildDB" if self.copr_event.chroot == COPR_SRPM_CHROOT else "CoprBuildDB"
             msg = f"Copr build {self.copr_event.build_id} not in {model}."
@@ -201,6 +211,7 @@ def run(self):
             )
             msg = "SRPM build in Copr has started..."
             self.set_start_time()
+            report_long_runtime("SRPM build start", 120, run_start_time)
             return TaskResults(success=True, details={"msg": msg})
 
         self.pushgateway.copr_builds_started.inc()
@@ -220,6 +231,7 @@ def run(self):
         )
         msg = f"Build on {self.copr_event.chroot} in copr has started..."
         self.set_start_time()
+        report_long_runtime("Copr build start", 120, run_start_time)
         return TaskResults(success=True, details={"msg": msg})
 
 
@@ -263,12 +275,15 @@ def measure_time_after_reporting(self):
             self.build.target,
         ).ended_on
 
+        build_ended_on_datetime = datetime.fromtimestamp(build_ended_on, timezone.utc)
         reported_after_time = elapsed_seconds(
-            begin=datetime.fromtimestamp(build_ended_on, timezone.utc),
+            begin=build_ended_on_datetime,
             end=reported_time,
         )
-        logger.debug(
-            f"Copr build end reported after {reported_after_time / 60} minutes.",
+        logger.info(
+            f"Copr build {self.build.build_id} for {self.build.target} "
+            f"reported after {reported_after_time / 60} minutes.\n"
+            f"Copr build ended at {build_ended_on_datetime} and was reported at {reported_time}."
         )
 
         self.pushgateway.copr_build_end_reported_after_time.observe(reported_after_time)
@@ -285,6 +300,13 @@ def set_built_packages(self):
         self.build.set_built_packages(built_packages)
 
     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"
@@ -338,6 +360,7 @@ def run(self):
                     logs_url=self.build.build_logs_url,
                 )
             self.build.set_status(BuildStatus.failure)
+            report_long_runtime("Copr build failed end", 120, run_start_time)
             return TaskResults(success=False, details={"msg": failed_msg})
 
         self.report_successful_build()
@@ -365,6 +388,7 @@ def run(self):
                     f"as this is only experimental functionality for now.",
                 )
 
+        report_long_runtime("Copr build end", 120, run_start_time)
         return TaskResults(success=True, details={})
 
     def report_successful_build(self):

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.")

packit_service/worker/tasks.py

@@ -120,6 +120,7 @@ def setup_loggers(logger, *args, **kwargs):
     logging.getLogger("sandcastle").setLevel(logging.INFO)
     # easier debugging
     logging.getLogger("packit").setLevel(logging.DEBUG)
+    logging.getLogger("packit_service").setLevel(logging.DEBUG)
 
     class CustomFormatter(logging.Formatter):
         def format(self, record):
@@ -149,6 +150,11 @@ def format(self, record):
         project = getenv("PROJECT", "packit")
         handler.setFormatter(RFC5424Formatter(msgid=project))
         logger.addHandler(handler)
+        # Also add to root logger to ensure all loggers (including child loggers) inherit it
+        root_logger = logging.getLogger()
+        # Check if handler already exists to avoid duplicates
+        if not any(isinstance(h, logging.handlers.SysLogHandler) for h in root_logger.handlers):
+            root_logger.addHandler(handler)
 
     package_versions = [
         ("OGR", ogr_version),