Adds / modifies logging for a few Jira service methods (#767)

Adds & modifies debug logging for
* get_issue
* create_issue
* update_issue_resolution

It also reuses the Atlassian library's client logger in our patched `raise_for_status` method, rather than the `jbi.services.jira` logger. This helps keep the concerns of different loggers separate.

Author: grahamalama

jbi/services/jira.py

@@ -16,6 +16,7 @@
 import requests
 from atlassian import Jira
 from atlassian import errors as atlassian_errors
+from atlassian.rest_client import log as atlassian_logger
 from requests import exceptions as requests_exceptions
 
 from jbi import Operation, environment
@@ -81,7 +82,7 @@ def raise_for_status(self, *args, **kwargs):
         except requests.HTTPError as exc:
             request = exc.request
             response = exc.response
-            logger.error(
+            atlassian_logger.error(
                 "HTTP: %s %s -> %s %s",
                 request.method,
                 request.path_url,
@@ -235,8 +236,15 @@ def _all_project_issue_types_exist(self, actions: Actions):
 
     def get_issue(self, context: ActionContext, issue_key):
         """Return the Jira issue fields or `None` if not found."""
+        logger.debug("Getting issue %s", issue_key, extra=context.model_dump())
         try:
-            return self.client.get_issue(issue_key)
+            response = self.client.get_issue(issue_key)
+            logger.debug(
+                "Received issue %s",
+                issue_key,
+                extra={"response": response, **context.model_dump()},
+            )
+            return response
         except requests_exceptions.HTTPError as exc:
             if getattr(exc.response, "status_code", None) != 404:
                 raise
@@ -253,33 +261,43 @@ def create_jira_issue(
     ):
         """Create a Jira issue with basic fields in the project and return its key."""
         bug = context.bug
-        logger.debug(
-            "Create new Jira issue for Bug %s",
-            bug.id,
-            extra=context.model_dump(),
-        )
         fields: dict[str, Any] = {
             "summary": bug.summary,
             "issuetype": {"name": issue_type},
             "description": description[:JIRA_DESCRIPTION_CHAR_LIMIT],
             "project": {"key": context.jira.project},
         }
-
-        jira_response_create = self.client.create_issue(fields=fields)
+        logger.debug(
+            "Creating new Jira issue for Bug %s",
+            bug.id,
+            extra={"fields": fields, **context.model_dump()},
+        )
+        try:
+            response = self.client.create_issue(fields=fields)
+        except requests.HTTPError as exc:
+            assert exc.response is not None
+            try:
+                response = exc.response.json()
+            except json.JSONDecodeError:
+                response = exc.response.text
+
+            logger.exception(
+                "Failed to create issue for Bug %s",
+                bug.id,
+                extra={"response": response, **context.model_dump()},
+            )
+            raise JiraCreateError(f"Failed to create issue for Bug {bug.id}") from exc
 
         # Jira response can be of the form: List or Dictionary
-        if isinstance(jira_response_create, list):
-            # if a list is returned, get the first item
-            jira_response_create = jira_response_create[0]
-
-        if isinstance(jira_response_create, dict):
-            # if a dict is returned or the first item in a list, confirm there are no errors
-            errs = ",".join(jira_response_create.get("errors", []))
-            msgs = ",".join(jira_response_create.get("errorMessages", []))
-            if errs or msgs:
-                raise JiraCreateError(errs + msgs)
-
-        return jira_response_create
+        # if a list is returned, get the first item
+        issue_data = response[0] if isinstance(response, list) else response
+        logger.debug(
+            "Jira issue %s created for Bug %s",
+            issue_data["key"],
+            bug.id,
+            extra={"response": response, **context.model_dump()},
+        )
+        return issue_data
 
     def add_jira_comment(self, context: ActionContext):
         """Publish a comment on the specified Jira issue"""
@@ -455,14 +473,22 @@ def update_issue_resolution(self, context: ActionContext, jira_resolution: str):
         assert issue_key  # Until we have more fine-grained typing of contexts
 
         logger.debug(
-            "Updating Jira resolution to %s",
+            "Updating resolution of Jira issue %s to %s",
+            issue_key,
             jira_resolution,
             extra=context.model_dump(),
         )
-        return self.client.update_issue_field(
+        response = self.client.update_issue_field(
             key=issue_key,
             fields={"resolution": jira_resolution},
         )
+        logger.debug(
+            "Updated resolution of Jira issue %s to %s",
+            issue_key,
+            jira_resolution,
+            extra={"response": response, **context.model_dump()},
+        )
+        return response
 
     def update_issue_components(
         self,

pyproject.toml

@@ -83,7 +83,7 @@ warn_return_any = true
 plugins = "pydantic.mypy"
 
 [[tool.mypy.overrides]]
-module = ["ruamel", "bugzilla", "atlassian", "statsd.defaults.env"]
+module = ["ruamel", "bugzilla", "atlassian", "atlassian.rest_client", "statsd.defaults.env"]
 ignore_missing_imports = true
 
 [[tool.mypy.overrides]]

tests/unit/services/test_jira.py

@@ -90,15 +90,14 @@ def test_jira_does_not_retry_4XX(mocked_responses, context_create_example):
     mocked_responses.add(
         responses.POST,
         url,
-        json={},
+        json={"errorMessages": ["You done goofed"]},
         status=400,
     )
 
-    with pytest.raises(requests.HTTPError):
+    with pytest.raises(jira.JiraCreateError):
         jira.get_service().create_jira_issue(
             context=context_create_example, description="", issue_type="Task"
         )
-
     assert len(mocked_responses.calls) == 1
 
 
@@ -155,3 +154,232 @@ def test_all_projects_components_exist_no_components_param(
     )
     result = jira.get_service()._all_projects_components_exist(actions)
     assert result is True
+
+
+def test_get_issue(mocked_responses, action_context_factory, capturelogs):
+    context = action_context_factory()
+    url = f"{get_settings().jira_base_url}rest/api/2/issue/JBI-234"
+    mock_response_data = {"key": "JBI-234", "fields": {"project": {"key": "JBI"}}}
+    mocked_responses.add(responses.GET, url, json=mock_response_data)
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        response = jira.get_service().get_issue(context=context, issue_key="JBI-234")
+
+    assert response == mock_response_data
+    for record in capturelogs.records:
+        assert record.rid == context.rid
+        assert record.action["whiteboard_tag"] == context.action.whiteboard_tag
+
+    before, after = capturelogs.messages
+    assert before == "Getting issue JBI-234"
+    assert after == "Received issue JBI-234"
+
+
+def test_get_issue_handles_404(mocked_responses, action_context_factory, capturelogs):
+    context = action_context_factory()
+    url = f"{get_settings().jira_base_url}rest/api/2/issue/JBI-234"
+    mocked_responses.add(responses.GET, url, status=404)
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        return_val = jira.get_service().get_issue(context=context, issue_key="JBI-234")
+
+    assert return_val is None
+
+    for record in capturelogs.records:
+        assert record.rid == context.rid
+
+    before, after = capturelogs.records
+    assert before.levelno == logging.DEBUG
+    assert before.message == "Getting issue JBI-234"
+
+    assert after.levelno == logging.ERROR
+    assert after.message.startswith("Could not read issue JBI-234")
+
+
+def test_get_issue_reraises_other_erroring_status_codes(
+    mocked_responses, action_context_factory, capturelogs
+):
+    context = action_context_factory()
+    url = f"{get_settings().jira_base_url}rest/api/2/issue/JBI-234"
+    mocked_responses.add(responses.GET, url, status=401)
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        with pytest.raises(requests.HTTPError):
+            jira.get_service().get_issue(context=context, issue_key="JBI-234")
+
+    [record] = capturelogs.records
+    assert record.rid == context.rid
+    assert record.levelno == logging.DEBUG
+    assert record.message == "Getting issue JBI-234"
+
+
+def test_update_issue_resolution(mocked_responses, action_context_factory, capturelogs):
+    context = action_context_factory(jira__issue="JBI-234")
+    url = f"{get_settings().jira_base_url}rest/api/2/issue/JBI-234"
+    mocked_responses.add(
+        responses.PUT,
+        url,
+        match=[
+            responses.matchers.json_params_matcher({"fields": {"resolution": "DONEZO"}})
+        ],
+    )
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        jira.get_service().update_issue_resolution(
+            context=context, jira_resolution="DONEZO"
+        )
+
+    for record in capturelogs.records:
+        assert record.rid == context.rid
+        assert record.levelno == logging.DEBUG
+
+    before, after = capturelogs.messages
+    assert before == "Updating resolution of Jira issue JBI-234 to DONEZO"
+    assert after == "Updated resolution of Jira issue JBI-234 to DONEZO"
+
+
+def test_update_issue_resolution_raises(
+    mocked_responses, action_context_factory, capturelogs
+):
+    context = action_context_factory(jira__issue="JBI-234")
+    url = f"{get_settings().jira_base_url}rest/api/2/issue/JBI-234"
+    mocked_responses.add(
+        responses.PUT,
+        url,
+        status=401,
+        match=[
+            responses.matchers.json_params_matcher({"fields": {"resolution": "DONEZO"}})
+        ],
+    )
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        with pytest.raises(requests.HTTPError):
+            jira.get_service().update_issue_resolution(
+                context=context, jira_resolution="DONEZO"
+            )
+
+    [record] = capturelogs.records
+    assert record.rid == context.rid
+    assert record.levelno == logging.DEBUG
+    assert record.message == "Updating resolution of Jira issue JBI-234 to DONEZO"
+
+
+def test_create_jira_issue(mocked_responses, action_context_factory, capturelogs):
+    context = action_context_factory(jira__project_key="JBI")
+    url = f"{get_settings().jira_base_url}rest/api/2/issue"
+    mocked_response_data = {"key": "JBI-234"}
+    issue_fields = {
+        "summary": context.bug.summary,
+        "issuetype": {"name": "Task"},
+        "description": "description",
+        "project": {"key": "JBI"},
+    }
+    mocked_responses.add(
+        responses.POST,
+        url,
+        status=201,
+        match=[
+            responses.matchers.json_params_matcher(
+                {"fields": issue_fields},
+            )
+        ],
+        json=mocked_response_data,
+    )
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        response = jira.get_service().create_jira_issue(
+            context=context, description="description", issue_type="Task"
+        )
+
+    assert response == mocked_response_data
+
+    for record in capturelogs.records:
+        assert record.rid == context.rid
+        assert record.levelno == logging.DEBUG
+
+    before, after = capturelogs.records
+    assert before.message == f"Creating new Jira issue for Bug {context.bug.id}"
+    assert before.fields == issue_fields
+
+    assert after.message == f"Jira issue JBI-234 created for Bug {context.bug.id}"
+    assert after.response == mocked_response_data
+
+
+def test_create_jira_issue_when_list_is_returned(
+    mocked_responses, action_context_factory, capturelogs
+):
+    context = action_context_factory(jira__project_key="JBI")
+    url = f"{get_settings().jira_base_url}rest/api/2/issue"
+    mocked_issue_data = {"key": "JBI-234"}
+    issue_fields = {
+        "summary": context.bug.summary,
+        "issuetype": {"name": "Task"},
+        "description": "description",
+        "project": {"key": "JBI"},
+    }
+    mocked_responses.add(
+        responses.POST,
+        url,
+        status=201,
+        match=[
+            responses.matchers.json_params_matcher(
+                {"fields": issue_fields},
+            )
+        ],
+        json=[mocked_issue_data],
+    )
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        issue_data = jira.get_service().create_jira_issue(
+            context=context, description="description", issue_type="Task"
+        )
+
+    assert issue_data == mocked_issue_data
+
+    before, after = capturelogs.records
+    assert before.message == f"Creating new Jira issue for Bug {context.bug.id}"
+    assert before.levelno == logging.DEBUG
+    assert before.rid == context.rid
+    assert before.fields == issue_fields
+
+    assert after.message == f"Jira issue JBI-234 created for Bug {context.bug.id}"
+    assert after.levelno == logging.DEBUG
+    assert after.rid == context.rid
+    assert after.response == [mocked_issue_data]
+
+
+def test_create_jira_issue_returns_errors(
+    mocked_responses, action_context_factory, capturelogs
+):
+    context = action_context_factory(jira__project_key="JBI")
+    url = f"{get_settings().jira_base_url}rest/api/2/issue"
+    fake_error_data = {
+        "errorMessages": ["You done goofed"],
+        "errors": ["You messed up this time"],
+    }
+    issue_fields = {
+        "summary": context.bug.summary,
+        "issuetype": {"name": "Task"},
+        "description": "description",
+        "project": {"key": "JBI"},
+    }
+    mocked_responses.add(responses.POST, url, status=400, json=fake_error_data)
+
+    with capturelogs.for_logger("jbi.services.jira").at_level(logging.DEBUG):
+        with pytest.raises(jira.JiraCreateError) as exc:
+            jira.get_service().create_jira_issue(
+                context=context, description="description", issue_type="Task"
+            )
+
+    assert str(exc.value) == "Failed to create issue for Bug 654321"
+
+    before, after = capturelogs.records
+    assert before.message == f"Creating new Jira issue for Bug {context.bug.id}"
+    assert before.rid == context.rid
+    assert before.levelno == logging.DEBUG
+    assert before.fields == issue_fields
+
+    assert after.message == f"Failed to create issue for Bug {context.bug.id}"
+    assert after.rid == context.rid
+    assert after.levelno == logging.ERROR
+    assert after.response == fake_error_data

tests/unit/test_steps.py

@@ -250,9 +250,7 @@ def test_added_comment(
 def test_jira_returns_an_error(
     context_create_example: ActionContext, mocked_jira, action_params_factory
 ):
-    mocked_jira.create_issue.return_value = [
-        {"errors": ["Boom"]},
-    ]
+    mocked_jira.create_issue.side_effect = [JiraCreateError("Boom")]
     callable_object = Executor(
         action_params_factory(jira_project_key=context_create_example.jira.project)
     )