Fix #958: add more logging fields to retry job exceptions (#959)

* Fix #958: add more logging fields to retry job exceptions

* Add item identifier to logs

* Add logging in runner when event fails

* Remove metrics from retry job logs

Author: leplatrem

jbi/queue.py

@@ -34,7 +34,7 @@
 from urllib.parse import ParseResult, urlparse
 
 import dockerflow.checks
-from pydantic import BaseModel, FileUrl, ValidationError
+from pydantic import BaseModel, FileUrl, ValidationError, computed_field
 
 from jbi import bugzilla
 from jbi.environment import get_settings
@@ -74,8 +74,9 @@ class QueueItem(BaseModel, frozen=True):
     def timestamp(self) -> datetime:
         return self.payload.event.time
 
+    @computed_field  # type: ignore
     @property
-    def identifier(self):
+    def identifier(self) -> str:
         return f"{self.payload.event.time}-{self.payload.bug.id}-{self.payload.event.action}-{"error" if self.error else "postponed"}"
 
 
@@ -271,7 +272,7 @@ async def postpone(self, payload: bugzilla.WebhookRequest) -> None:
 
     async def track_failed(
         self, payload: bugzilla.WebhookRequest, exc: Exception
-    ) -> None:
+    ) -> QueueItem:
         """
         Store the specified payload and exception information into the queue.
         """
@@ -280,6 +281,7 @@ async def track_failed(
             error=PythonException.from_exc(exc),
         )
         await self.backend.put(item)
+        return item
 
     async def is_blocked(self, payload: bugzilla.WebhookRequest) -> bool:
         """

jbi/retry.py

@@ -52,8 +52,15 @@ async def retry_failed(item_executor=runner.execute_action, queue=get_dl_queue()
                     await queue.done(item)
                     metrics["events_processed"] += 1
                 except Exception:
-                    logger.exception("failed to reprocess event %s.", item.identifier)
                     metrics["events_failed"] += 1
+                    logger.exception(
+                        "failed to reprocess event %s.",
+                        item.identifier,
+                        extra={
+                            "item": item.model_dump(),
+                            "bug": {"id": bug_id},
+                        },
+                    )
 
                     # check for other events that will be skipped
                     pending_events = await queue.size(bug_id)
@@ -67,8 +74,12 @@ async def retry_failed(item_executor=runner.execute_action, queue=get_dl_queue()
                         metrics["events_skipped"] += pending_events - 1
                         break
         except Exception:
-            logger.exception("failed to parse events for bug %d.", bug_id)
             metrics["bugs_failed"] += 1
+            logger.exception(
+                "failed to parse events for bug %d.",
+                bug_id,
+                extra={"bug": {"id": bug_id}},
+            )
 
     return metrics
 

jbi/runner.py

@@ -177,7 +177,17 @@ async def execute_or_queue(
     except IgnoreInvalidRequestError as exc:
         return {"status": "invalid", "error": str(exc)}
     except Exception as exc:
-        await queue.track_failed(request, exc)
+        item = await queue.track_failed(request, exc)
+        logger.exception(
+            "Failed to process %r event on Bug %s. %s was put in queue.",
+            request.event.action,
+            request.bug.id,
+            item.identifier,
+            extra={
+                "payload": request.model_dump(),
+                "item": item.model_dump(),
+            },
+        )
         return {"status": "failed", "error": str(exc)}