Improve logging and status reporting of actions (#155)

* Add operation field in log context of most actions logging

* Replace action execution status with typed Operation

* Document and add specific for actions return values

* Rewrite Operations enum with Graham's pattern

* Return True/False instead of operation

* Log level has to be set explicitly in tests

* Update action docs

Author: leplatrem

src/jbi/__init__.py

@@ -0,0 +1,25 @@
+"""
+Module domain specific code related to JBI.
+
+This part of the code is not aware of the HTTP context it runs in.
+"""
+from enum import Enum
+from typing import Dict, Tuple
+
+
+class Operation(str, Enum):
+    """Enumeration of possible operations logged during WebHook execution."""
+
+    HANDLE = "handle"
+    EXECUTE = "execute"
+    IGNORE = "ignore"
+    SUCCESS = "success"
+
+    CREATE = "create"
+    UPDATE = "update"
+    DELETE = "delete"
+    COMMENT = "comment"
+    LINK = "link"
+
+
+ActionResult = Tuple[bool, Dict]

src/jbi/runner.py

@@ -6,22 +6,14 @@
 from statsd.defaults.env import statsd
 
 from src.app.environment import Settings
+from src.jbi import Operation
 from src.jbi.bugzilla import BugzillaBug, BugzillaWebhookRequest
 from src.jbi.errors import ActionNotFoundError, IgnoreInvalidRequestError
 from src.jbi.models import Actions
 
 logger = logging.getLogger(__name__)
 
 
-class Operations:
-    """Track status of incoming requests in log entries."""
-
-    HANDLE = "handle"
-    EXECUTE = "execute"
-    IGNORE = "ignore"
-    SUCCESS = "success"
-
-
 @statsd.timer("jbi.action.execution.timer")
 def execute_action(
     request: BugzillaWebhookRequest,
@@ -44,7 +36,7 @@ def execute_action(
     try:
         logger.debug(
             "Handling incoming request",
-            extra={"operation": Operations.HANDLE, **log_context},
+            extra={"operation": Operation.HANDLE, **log_context},
         )
         if not request.bug:
             raise IgnoreInvalidRequestError("no bug data received")
@@ -77,24 +69,27 @@ def execute_action(
             action.whiteboard_tag,
             action.module,
             bug_obj.id,
-            extra={"operation": Operations.EXECUTE, **log_context},
+            extra={"operation": Operation.EXECUTE, **log_context},
         )
 
-        content = action.caller(payload=request)
+        handled, details = action.caller(payload=request)
 
         logger.info(
             "Action %r executed successfully for Bug %s",
             action.whiteboard_tag,
             bug_obj.id,
-            extra={"operation": Operations.SUCCESS, **log_context},
+            extra={
+                "operation": Operation.SUCCESS if handled else Operation.IGNORE,
+                **log_context,
+            },
         )
         statsd.incr("jbi.bugzilla.processed.count")
-        return content
+        return details
     except IgnoreInvalidRequestError as exception:
         logger.debug(
             "Ignore incoming request: %s",
             exception,
-            extra={"operation": Operations.IGNORE, **log_context},
+            extra={"operation": Operation.IGNORE, **log_context},
         )
         statsd.incr("jbi.bugzilla.ignored.count")
         raise

src/jbi/whiteboard_actions/README.md

@@ -7,13 +7,21 @@ Let's create a `new_action`!
 1. First, add a new Python file (eg. `my_team_action.py`) in the `src/jbi/whiteboard_actions/` directory.
 1. Add the Python function `init` to the module, for example:
     ```python
+    from src.jbi import ActionResult, Operation
+
     def init(jira_project_key, optional_param=42):
-        return lambda payload: print(f"{optional_param}, going to {jira_project_key}!")
+
+        def execute(payload) -> ActionResult:
+            print(f"{optional_param}, going to {jira_project_key}!")
+            return True, {"result": 42}
+
+        return execute
     ```
     1. In the above example the `jira_project_key` parameter is required
     1. `optional_param`, which has a default value, is not required to run this action
     1. `init()` returns a `__call__`able object that the system calls with the Bugzilla request payload
+    1.  The returned `ActionResult` features a boolean to indicate whether something was performed or not, along with a `Dict` (used as a response to the WebHook endpoint).
 1. Use the `payload` to perform the desired processing!
-1. Use the available service calls from `src/jbi/services.py' (or make new ones)
+1. Use the available service calls from `src/jbi/services.py` (or make new ones)
 1. Update the `README.md` to document your action
 1. Now the action `src.jbi.whiteboard_actions.my_team_actions` can be used in the YAML configuration, under the `module` key.

src/jbi/whiteboard_actions/default.py

@@ -7,6 +7,7 @@
 import logging
 
 from src.app.environment import get_settings
+from src.jbi import ActionResult, Operation
 from src.jbi.bugzilla import BugzillaBug, BugzillaWebhookRequest
 from src.jbi.errors import ActionError
 from src.jbi.services import get_bugzilla, get_jira
@@ -33,7 +34,7 @@ def __init__(self, jira_project_key, **kwargs):
 
     def __call__(  # pylint: disable=inconsistent-return-statements
         self, payload: BugzillaWebhookRequest
-    ):
+    ) -> ActionResult:
         """Called from BZ webhook when default action is used. All default-action webhook-events are processed here."""
         target = payload.event.target  # type: ignore
         if target == "comment":
@@ -45,17 +46,20 @@ def __call__(  # pylint: disable=inconsistent-return-statements
             target,
             extra={
                 "request": payload.dict(),
+                "operation": Operation.IGNORE,
             },
         )
+        return False, {}
 
-    def comment_create_or_noop(self, payload: BugzillaWebhookRequest):
+    def comment_create_or_noop(self, payload: BugzillaWebhookRequest) -> ActionResult:
         """Confirm issue is already linked, then apply comments; otherwise noop"""
         bug_obj = payload.bugzilla_object
         linked_issue_key = bug_obj.extract_from_see_also()
 
         log_context = {
             "request": payload.dict(),
             "bug": bug_obj.dict(),
+            "operation": Operation.COMMENT,
             "jira": {
                 "issue": linked_issue_key,
                 "project": self.jira_project_key,
@@ -67,11 +71,15 @@ def comment_create_or_noop(self, payload: BugzillaWebhookRequest):
                 bug_obj.id,
                 extra=log_context,
             )
-            return {"status": "noop"}
+            return False, {}
 
         comment = payload.map_as_jira_comment()
         if comment is None:
-            return {"status": "noop"}
+            logger.debug(
+                "No matching comment found in payload",
+                extra=log_context,
+            )
+            return False, {}
 
         jira_response = self.jira_client.issue_add_comment(
             issue_key=linked_issue_key,
@@ -82,7 +90,7 @@ def comment_create_or_noop(self, payload: BugzillaWebhookRequest):
             linked_issue_key,
             extra=log_context,
         )
-        return {"status": "comment", "jira_response": jira_response}
+        return True, {"jira_response": jira_response}
 
     def jira_comments_for_update(
         self,
@@ -102,7 +110,7 @@ def update_issue(
 
     def bug_create_or_update(
         self, payload: BugzillaWebhookRequest
-    ):  # pylint: disable=too-many-locals
+    ) -> ActionResult:  # pylint: disable=too-many-locals
         """Create and link jira issue with bug, or update; rollback if multiple events fire"""
         bug_obj = payload.bugzilla_object
         linked_issue_key = bug_obj.extract_from_see_also()  # type: ignore
@@ -121,7 +129,10 @@ def bug_create_or_update(
             "Update fields of Jira issue %s for Bug %s",
             linked_issue_key,
             bug_obj.id,
-            extra=log_context,
+            extra={
+                **log_context,
+                "operation": Operation.LINK,
+            },
         )
         jira_response_update = self.jira_client.update_issue_field(
             key=linked_issue_key, fields=bug_obj.map_as_jira_issue()
@@ -134,7 +145,10 @@ def bug_create_or_update(
                 "Create comment #%s on Jira issue %s",
                 i + 1,
                 linked_issue_key,
-                extra=log_context,
+                extra={
+                    **log_context,
+                    "operation": Operation.COMMENT,
+                },
             )
             jira_response_comments.append(
                 self.jira_client.issue_add_comment(
@@ -144,14 +158,11 @@ def bug_create_or_update(
 
         self.update_issue(payload, bug_obj, linked_issue_key, is_new=False)
 
-        return {
-            "status": "update",
-            "jira_responses": [jira_response_update, jira_response_comments],
-        }
+        return True, {"jira_responses": [jira_response_update, jira_response_comments]}
 
-    def create_and_link_issue(
+    def create_and_link_issue(  # pylint: disable=too-many-locals
         self, payload, bug_obj
-    ):  # pylint: disable=too-many-locals
+    ) -> ActionResult:
         """create jira issue and establish link between bug and issue; rollback/delete if required"""
         log_context = {
             "request": payload.dict(),
@@ -163,7 +174,10 @@ def create_and_link_issue(
         logger.debug(
             "Create new Jira issue for Bug %s",
             bug_obj.id,
-            extra=log_context,
+            extra={
+                **log_context,
+                "operation": Operation.CREATE,
+            },
         )
         comment_list = self.bugzilla_client.get_comments(idlist=[bug_obj.id])
         fields = {
@@ -205,19 +219,25 @@ def create_and_link_issue(
                 "Delete duplicated Jira issue %s from Bug %s",
                 jira_key_in_response,
                 bug_obj.id,
-                extra=log_context,
+                extra={
+                    **log_context,
+                    "operation": Operation.DELETE,
+                },
             )
             jira_response_delete = self.jira_client.delete_issue(
                 issue_id_or_key=jira_key_in_response
             )
-            return {"status": "duplicate", "jira_response": jira_response_delete}
+            return True, {"jira_response": jira_response_delete}
 
         jira_url = f"{settings.jira_base_url}browse/{jira_key_in_response}"
         logger.debug(
             "Link %r on Bug %s",
             jira_url,
             bug_obj.id,
-            extra=log_context,
+            extra={
+                **log_context,
+                "operation": Operation.LINK,
+            },
         )
         update = self.bugzilla_client.build_update(see_also_add=jira_url)
         bugzilla_response = self.bugzilla_client.update_bugs([bug_obj.id], update)
@@ -227,7 +247,10 @@ def create_and_link_issue(
             "Link %r on Jira issue %s",
             bugzilla_url,
             jira_key_in_response,
-            extra=log_context,
+            extra={
+                **log_context,
+                "operation": Operation.LINK,
+            },
         )
         jira_response = self.jira_client.create_or_update_issue_remote_links(
             issue_key=jira_key_in_response,
@@ -237,8 +260,7 @@ def create_and_link_issue(
 
         self.update_issue(payload, bug_obj, jira_key_in_response, is_new=True)
 
-        return {
-            "status": "create",
+        return True, {
             "bugzilla_response": bugzilla_response,
             "jira_response": jira_response,
         }

src/jbi/whiteboard_actions/default_with_assignee_and_status.py

@@ -9,6 +9,7 @@
 """
 import logging
 
+from src.jbi import Operation
 from src.jbi.bugzilla import BugzillaBug, BugzillaWebhookRequest
 from src.jbi.whiteboard_actions.default import DefaultExecutor
 
@@ -58,6 +59,7 @@ def update_issue(
                 "project": self.jira_project_key,
             },
             "changed_fields": changed_fields,
+            "operation": Operation.UPDATE,
         }
 
         def clear_assignee():
@@ -99,7 +101,10 @@ def clear_assignee():
                         # assignee.
                         clear_assignee()
                 else:
-                    logger.debug("No assignee found", extra=log_context)
+                    logger.debug(
+                        "No assignee found",
+                        extra={**log_context, "operation": Operation.IGNORE},
+                    )
                     clear_assignee()
 
         # If this is a new issue or if the bug's status or resolution has
@@ -120,5 +125,9 @@ def clear_assignee():
             else:
                 logger.debug(
                     "Bug status was not in the status map.",
-                    extra={**log_context, "status_map": self.status_map},
+                    extra={
+                        **log_context,
+                        "status_map": self.status_map,
+                        "operation": Operation.IGNORE,
+                    },
                 )

tests/unit/jbi/noop_action.py

@@ -4,7 +4,11 @@
 
 `init` should return a __call__able
 """
+from src.jbi import Operation
 
 
 def init(**parameters):
-    return lambda payload: {"parameters": parameters, "payload": payload.json()}
+    return lambda payload: (
+        True,
+        {"parameters": parameters, "payload": payload.json()},
+    )