Improve logging using context (fixes #73) (#74)

Author: leplatrem

src/app/log.py

@@ -30,8 +30,7 @@ def configure_logging():
         },
         "loggers": {
             "request.summary": {"handlers": ["console"], "level": "INFO"},
-            "src.jbi": {"handlers": ["console"], "level": "INFO"},
-            "ignored-requests": {"handlers": ["console"], "level": "DEBUG"},
+            "src.jbi": {"handlers": ["console"], "level": "DEBUG"},
         },
     }
 

src/jbi/bugzilla.py

@@ -6,13 +6,14 @@
 import datetime
 import json
 import logging
-import traceback
 from typing import Dict, List, Optional
 from urllib.parse import ParseResult, urlparse
 
 from pydantic import BaseModel  # pylint: disable=no-name-in-module
 
-bugzilla_logger = logging.getLogger("src.jbi.bugzilla")
+logger = logging.getLogger(__name__)
+
+JIRA_HOSTNAMES = ("jira", "atlassian")
 
 
 class BugzillaWebhookUser(BaseModel):
@@ -166,16 +167,25 @@ def extract_from_see_also(self):
         for url in self.see_also:  # pylint: disable=not-an-iterable
             try:
                 parsed_url: ParseResult = urlparse(url=url)
-                expected_hosts = ["jira", "atlassian"]
+                host_parts = parsed_url.hostname.split(".")
+            except (ValueError, AttributeError):
+                logger.debug(
+                    "Bug %s `see_also` is not a URL: %s",
+                    self.id,
+                    url,
+                    extra={
+                        "bug": {
+                            "id": self.id,
+                        }
+                    },
+                )
+                continue
 
-                if any(  # pylint: disable=use-a-generator
-                    [part in expected_hosts for part in parsed_url.hostname.split(".")]
-                ):
-                    parsed_jira_key = parsed_url.path.split("/")[-1]
+            if any(part in JIRA_HOSTNAMES for part in host_parts):
+                parsed_jira_key = parsed_url.path.rstrip("/").split("/")[-1]
+                if parsed_jira_key:  # URL ending with /
                     return parsed_jira_key
-            except Exception:  # pylint: disable=broad-except
-                # Try parsing all see_also fields; log errors.
-                bugzilla_logger.debug(traceback.format_exc())
+
         return None
 
 

src/jbi/configuration.py

@@ -10,7 +10,7 @@
 from src.jbi.models import Actions
 
 settings = environment.get_settings()
-jbi_logger = logging.getLogger("src.jbi")
+logger = logging.getLogger(__name__)
 
 
 class ConfigError(Exception):
@@ -29,7 +29,7 @@ def get_actions(
             actions: Actions = Actions.parse_raw(yaml_data)
             return actions
         except ValidationError as exception:
-            jbi_logger.exception(exception)
+            logger.exception(exception)
             raise ConfigError("Errors exist.") from exception
 
 

src/jbi/models.py

@@ -58,7 +58,7 @@ def validate_action_matches_whiteboard(
         if not actions:
             raise ValueError("no actions configured")
         for name, action in actions.items():
-            if name != action.parameters["whiteboard_tag"]:
+            if name.lower() != action.parameters["whiteboard_tag"]:
                 raise ValueError("action name must match whiteboard tag")
 
         return actions

src/jbi/router.py

@@ -4,7 +4,7 @@
 import importlib
 import logging
 from types import ModuleType
-from typing import Dict, List, Optional
+from typing import Dict, List, Mapping, Optional, Tuple
 
 from fastapi import APIRouter, Body, Depends, Request
 from fastapi.responses import HTMLResponse, JSONResponse
@@ -20,53 +20,93 @@
 
 api_router = APIRouter(tags=["JBI"])
 
-jbi_logger = logging.getLogger("src.jbi.router")
-invalid_logger = logging.getLogger("ignored-requests")
+logger = logging.getLogger(__name__)
 
 
-def extract_current_action(  # pylint: disable=inconsistent-return-statements
-    bug_obj: BugzillaBug, action_map
-):
+class Operations:
+    """Track status of incoming requests in log entries."""
+
+    HANDLE = "handle"
+    EXECUTE = "execute"
+    IGNORE = "ignore"
+    SUCCESS = "success"
+
+
+def extract_current_action(
+    bug_obj: BugzillaBug, action_map: Mapping[str, Dict]
+) -> Optional[Tuple[str, Dict]]:
     """Find first matching action from bug's whiteboard list"""
     potential_configuration_tags: List[
         str
     ] = bug_obj.get_potential_whiteboard_config_list()
 
     for tag in potential_configuration_tags:
         if action := action_map.get(tag.lower()):
-            return action
+            return tag.lower(), action
+    return None
 
 
-def execute_action(request: BugzillaWebhookRequest, action_map, settings):
+def execute_action(
+    request: BugzillaWebhookRequest,
+    action_map: Mapping[str, Dict],
+    settings: environment.Settings,
+):
     """Execute action"""
+    log_context = {
+        "bug": {
+            "id": request.bug.id if request.bug else None,
+        },
+        "request": request.json(),
+    }
     try:
-        jbi_logger.info("request: %s", request.json())
+        logger.debug(
+            "Handling incoming request",
+            extra={"operation": Operations.HANDLE, **log_context},
+        )
         if not request.bug:
             raise IgnoreInvalidRequestError("no bug data received")
 
         bug_obj = getbug_as_bugzilla_object(request=request)
-        current_action = extract_current_action(bug_obj, action_map)  # type: ignore
+        log_context["bug"] = bug_obj.json()
 
-        if not current_action:
+        action_item = extract_current_action(bug_obj, action_map)
+        if not action_item:
             raise IgnoreInvalidRequestError(
                 "whiteboard tag not found in configured actions"
             )
 
+        action_name, current_action = action_item
+        log_context["action"] = current_action
+
         if bug_obj.is_private and not current_action["allow_private"]:
             raise IgnoreInvalidRequestError(
-                "private bugs are not valid for this action"
+                f"private bugs are not valid for action {action_name!r}"
             )
 
-        jbi_logger.info("\nrequest: %s, \naction: %s", request.json(), current_action)
+        logger.info(
+            "Execute action %r for Bug %s",
+            action_name,
+            bug_obj.id,
+            extra={"operation": Operations.EXECUTE, **log_context},
+        )
         action_module: ModuleType = importlib.import_module(current_action["action"])
         callable_action = action_module.init(  # type: ignore
             **current_action["parameters"]
         )
         content = callable_action(payload=request)
-        jbi_logger.info("request: %s, content: %s", request.json(), content)
+        logger.info(
+            "Action %r executed successfully for Bug %s",
+            action_name,
+            bug_obj.id,
+            extra={"operation": Operations.SUCCESS, **log_context},
+        )
         return JSONResponse(content=content, status_code=200)
     except IgnoreInvalidRequestError as exception:
-        invalid_logger.debug("ignore-invalid-request: %s", exception)
+        logger.debug(
+            "Ignore incoming request: %s",
+            exception,
+            extra={"operation": Operations.IGNORE, **log_context},
+        )
         return JSONResponse(content={"error": str(exception)}, status_code=200)
 
 

src/jbi/services.py

@@ -1,5 +1,4 @@
 """Services and functions that can be used to create custom actions"""
-import logging
 from typing import Dict, List
 
 import bugzilla as rh_bugzilla  # type: ignore
@@ -9,7 +8,6 @@
 from src.jbi.bugzilla import BugzillaBug, BugzillaWebhookRequest
 
 settings = environment.get_settings()
-services_logger = logging.getLogger("src.jbi.services")
 
 
 def get_jira():

tests/unit/jbi/test_bugzilla.py

@@ -42,3 +42,25 @@ def test_get_jira_labels_multiple():
         "[test-both.space-and-not]",
     ]
     assert expected == jira_labels
+
+
+@pytest.mark.parametrize(
+    "see_also,expected",
+    [
+        ([], None),
+        (["foo"], None),
+        (["fail:/format"], None),
+        (["foo", "http://jira.net/123"], "123"),
+        (["http://bugzilla.org/123"], None),
+        (["http://jira.com"], None),
+        (["http://mozilla.jira.com/"], None),
+        (["http://mozilla.jira.com/123"], "123"),
+        (["http://mozilla.jira.com/123/"], "123"),
+        (["http://mozilla.jira.com/ticket/123"], "123"),
+        (["http://atlassian.com/ticket/123"], "123"),
+        (["http://mozilla.jira.com/123", "http://mozilla.jira.com/456"], "123"),
+    ],
+)
+def test_extract_see_also(see_also, expected):
+    test_bug = bugzilla.BugzillaBug(id=0, see_also=see_also)
+    assert test_bug.extract_from_see_also() == expected

tests/unit/jbi/test_router.py

@@ -21,7 +21,7 @@ def test_request_is_ignored_because_private(
     test_action = Action.parse_obj({"action": "tests.unit.jbi.noop_action"}).dict()
 
     with mock.patch("src.jbi.router.extract_current_action") as mocked_extract_action:
-        mocked_extract_action.return_value = test_action
+        mocked_extract_action.return_value = "test", test_action
         with mock.patch("src.jbi.router.getbug_as_bugzilla_object") as mocked_bz_func:
             mocked_bz_func.return_value = private_webhook_request_example.bug
             with TestClient(app) as anon_client:
@@ -34,17 +34,17 @@ def test_request_is_ignored_because_private(
                 assert response.status_code == 200
                 assert (
                     response.json()["error"]
-                    == "private bugs are not valid for this action"
+                    == "private bugs are not valid for action 'test'"
                 )
 
-                invalid_request_logs = caplog.records[1]
-                assert invalid_request_logs.name == "ignored-requests"
+                captured_log_msgs = [
+                    r.msg % r.args for r in caplog.records if r.name == "src.jbi.router"
+                ]
 
-                assert invalid_request_logs.msg == "ignore-invalid-request: %s"
-                assert invalid_request_logs.args
-                for arg in invalid_request_logs.args:
-                    assert isinstance(arg, IgnoreInvalidRequestError)
-                    assert str(arg) == "private bugs are not valid for this action"
+                assert captured_log_msgs == [
+                    "Handling incoming request",
+                    "Ignore incoming request: private bugs are not valid for action 'test'",
+                ]
 
 
 def test_private_request_is_allowed(
@@ -57,7 +57,7 @@ def test_private_request_is_allowed(
     ).dict()
 
     with mock.patch("src.jbi.router.extract_current_action") as mocked_extract_action:
-        mocked_extract_action.return_value = test_action
+        mocked_extract_action.return_value = "test", test_action
         with mock.patch("src.jbi.router.getbug_as_bugzilla_object") as mocked_bz_func:
             mocked_bz_func.return_value = private_webhook_request_example.bug
             with TestClient(app) as anon_client:
@@ -88,14 +88,14 @@ def test_request_is_ignored_because_no_bug(
         assert response.status_code == 200
         assert response.json()["error"] == "no bug data received"
 
-        invalid_request_logs = caplog.records[1]
-        assert invalid_request_logs.name == "ignored-requests"
+        captured_log_msgs = [
+            r.msg % r.args for r in caplog.records if r.name == "src.jbi.router"
+        ]
 
-        assert invalid_request_logs.msg == "ignore-invalid-request: %s"
-        assert invalid_request_logs.args
-        for arg in invalid_request_logs.args:
-            assert isinstance(arg, IgnoreInvalidRequestError)
-            assert str(arg) == "no bug data received"
+        assert captured_log_msgs == [
+            "Handling incoming request",
+            "Ignore incoming request: no bug data received",
+        ]
 
 
 def test_request_is_ignored_because_no_action(
@@ -120,11 +120,11 @@ def test_request_is_ignored_because_no_action(
                     == "whiteboard tag not found in configured actions"
                 )
 
-                invalid_request_logs = caplog.records[1]
-                assert invalid_request_logs.name == "ignored-requests"
+                captured_log_msgs = [
+                    r.msg % r.args for r in caplog.records if r.name == "src.jbi.router"
+                ]
 
-                assert invalid_request_logs.msg == "ignore-invalid-request: %s"
-                assert invalid_request_logs.args
-                for arg in invalid_request_logs.args:
-                    assert isinstance(arg, IgnoreInvalidRequestError)
-                    assert str(arg) == "whiteboard tag not found in configured actions"
+                assert captured_log_msgs == [
+                    "Handling incoming request",
+                    "Ignore incoming request: whiteboard tag not found in configured actions",
+                ]