Better logging on workflow job events (#461)

Author: tcarmet

runner_manager/jobs/workflow_job.py

@@ -1,27 +1,43 @@
 from __future__ import annotations
 
+import logging
+
 from githubkit.webhooks.models import (
     WorkflowJobCompleted,
     WorkflowJobInProgress,
     WorkflowJobQueued,
 )
+from githubkit.webhooks.types import WorkflowJobEvent
 
 from runner_manager.clients.github import GitHub
 from runner_manager.dependencies import get_github
-from runner_manager.logging import log
 from runner_manager.models.runner import Runner
 from runner_manager.models.runner_group import RunnerGroup
 
+log = logging.getLogger(__name__)
+
+
+def log_workflow_job(webhook: WorkflowJobEvent) -> None:
+    log.info(
+        f"Starting workflow_job event (status: {webhook.workflow_job.status}, "
+        f"conclusion: {webhook.workflow_job.conclusion}, "
+        f"repository: {webhook.repository.full_name})"
+    )
+
 
 def completed(webhook: WorkflowJobCompleted) -> int:
-    log.info(f"Starting {webhook.action} workflow_job event")
+    log_workflow_job(webhook)
+    runner: Runner | None = Runner.find_from_webhook(webhook)
+    if not runner:
+        log.info(f"Runner {webhook.workflow_job.runner_name} not found")
+        return 0
     runner_group: RunnerGroup | None = RunnerGroup.find_from_webhook(webhook)
-    runner: Runner = Runner.find_from_webhook(webhook)
-    if not runner_group or not runner:
-        log.warning(f"Runner {webhook.workflow_job.runner_name} not found")
+    if not runner_group:
+        log.warning(f"Runner group for {runner} not found")
         return 0
+    log.info(f"Found {runner_group} for {runner}")
     github: GitHub = get_github()
-    log.info(f"Deleting runner {runner.name} in group {runner_group.name}")
+    log.info(f"Deleting runner {runner} in group {runner_group}")
     delete = runner_group.delete_runner(runner, github)
     if runner_group.need_new_runner:
         log.info(f"Runner group {runner_group.name} needs a new runner")
@@ -30,7 +46,7 @@ def completed(webhook: WorkflowJobCompleted) -> int:
 
 
 def in_progress(webhook: WorkflowJobInProgress) -> str | None:
-    log.info(f"Starting {webhook.action} workflow_job event")
+    log_workflow_job(webhook)
     name: str | None = webhook.workflow_job.runner_name
     runner_group: RunnerGroup | None = RunnerGroup.find_from_webhook(webhook)
     if not runner_group:
@@ -43,7 +59,7 @@ def in_progress(webhook: WorkflowJobInProgress) -> str | None:
 
 
 def queued(webhook: WorkflowJobQueued) -> str | None:
-    log.info(f"Starting {webhook.action} workflow_job event")
+    log_workflow_job(webhook)
     labels = webhook.workflow_job.labels
     log.info(f"Finding runner group with labels {labels}")
     runner_group: RunnerGroup = RunnerGroup.find_from_labels(
@@ -52,9 +68,7 @@ def queued(webhook: WorkflowJobQueued) -> str | None:
     if not runner_group:
         log.warning(f"Runner group with labels {labels} not found")
         return None
-    log.info(f"Found runner group {runner_group.name}")
-    log.info(f"Creating registration token for runner {runner_group.name}")
     github: GitHub = get_github()
-    log.info("Registration token created.")
+    log.info(f"Creating runner for {runner_group}")
     runner: Runner | None = runner_group.create_runner(github)
     return runner.pk if runner else None

runner_manager/models/runner.py

@@ -72,8 +72,11 @@ class Runner(BaseModel):
     created_at: Optional[datetime]
     started_at: Optional[datetime]
 
+    def __str__(self):
+        return f"self.name (status: {self.status}, busy: {self.busy})"
+
     @classmethod
-    def find_from_webhook(cls, webhook: WorkflowJobEvent) -> "Runner":
+    def find_from_webhook(cls, webhook: WorkflowJobEvent) -> "Runner | None":
         """Find a runner from a webhook payload
 
         Args:

runner_manager/models/runner_group.py

@@ -63,6 +63,12 @@ class RunnerGroup(BaseModel, BaseRunnerGroup):
     os: str = Field(default="linux")
     arch: str = Field(default="x64")
 
+    def __str__(self) -> str:
+        return (
+            f"{self.name} (max: {self.max}, min: {self.min}, "
+            f"current: {len(self.get_runners())}, queued: {self.queued})"
+        )
+
     def __post_init_post_parse__(self):
         """Post init."""
         super().__post_init_post_parse__()