[NDR-38] Improve PDS Logging (#634)

Author: robg-nhs

lambdas/services/pds_api_service.py

@@ -42,9 +42,12 @@ def pds_request(self, nhs_number: str, retry_on_expired: bool):
             }
 
             url_endpoint = endpoint + "Patient/" + nhs_number
+
+            logger.info("PDS Call Initiated")
             pds_response = self.session.get(
                 url=url_endpoint, headers=authorization_header
             )
+            logger.info("PDS Call Completed")
 
             if pds_response.status_code == 401 and retry_on_expired:
                 return self.pds_request(nhs_number, retry_on_expired=False)

lambdas/tests/unit/services/test_pds_api_service.py

@@ -97,6 +97,7 @@ def test_pds_request_valid_token_expired_response(mocker):
     second_response._content = json.dumps(PDS_PATIENT).encode("utf-8")
     nhs_number = "1111111111"
     mock_url_endpoint = "api.test/endpoint/Patient/" + nhs_number
+    time_now = 1600000000
 
     mock_authorization_header = {
         "Authorization": f"Bearer {ACCESS_TOKEN}",
@@ -107,7 +108,13 @@ def test_pds_request_valid_token_expired_response(mocker):
         "services.pds_api_service.PdsApiService.get_endpoint_for_pds_api_request",
         return_value="api.test/endpoint/",
     )
-    mocker.patch("time.time", side_effect=[1600000000.953031, 1700000000.953031])
+
+    # Logging calls invoke time.time, the first and last in the array are log calls
+    # The second and third are used during invocation of the PDS service.
+    mocker.patch(
+        "time.time",
+        side_effect=[time_now, 1600000000.953031, 1700000000.953031, time_now],
+    )
 
     mocker.patch("uuid.uuid4", return_value="123412342")