Merge pull request #1778 from uktrade/dev

UAT release extended

api/cases/views/views.py

@@ -1,3 +1,5 @@
+import logging
+
 from django.core.exceptions import PermissionDenied
 from django.db import transaction
 from django.http.response import JsonResponse, HttpResponse
@@ -954,6 +956,8 @@ def put(self, request, pk):
                 )
 
             licence.decisions.set([Decision.objects.get(name=decision) for decision in required_decisions])
+
+            logging.info("Initiate issue of licence %s (status: %s)", licence.reference_code, licence.status)
             licence.issue()
 
             return_payload["licence"] = licence.id
@@ -976,6 +980,7 @@ def put(self, request, pk):
         old_status = case.status.status
         case.status = get_case_status_by_status(CaseStatusEnum.FINALISED)
         case.save()
+        logging.info("Case status is now finalised")
 
         decisions = required_decisions.copy()
 
@@ -1017,6 +1022,8 @@ def put(self, request, pk):
         for document in documents:
             document.send_exporter_notifications()
 
+        logging.info("Licence documents visible to exporter, notification sent")
+
         return JsonResponse(return_payload, status=status.HTTP_201_CREATED)
 
 

api/conf/settings.py

@@ -114,6 +114,8 @@
     "health_check.cache",
     "health_check.storage",
     "health_check.contrib.migrations",
+    "health_check.contrib.celery",
+    "health_check.contrib.celery_ping",
     "django_audit_log_middleware",
     "lite_routing",
     "api.appeals",

api/licences/celery_tasks.py

@@ -10,7 +10,6 @@
 MAX_ATTEMPTS = 5
 RETRY_BACKOFF = 1200
 
-
 logger = get_task_logger(__name__)
 
 
@@ -28,8 +27,16 @@ def send_licence_details_to_lite_hmrc(licence_id, action):
     """
     try:
         with transaction.atomic():
-            # transaction.atomic + select_for_update + nowait=True will throw an error if row has already been locked
-            licence = Licence.objects.select_for_update(nowait=True).get(id=licence_id)
+            # It is essential to use select_for_update() without nowait=True because
+            # if lock is not available then we need to wait here till it is available.
+            #
+            # This task is scheduled when licence is issued which is already part of a transaction.
+            # Licence row would've already been locked during that transaction so if continue
+            # without waiting it will result in OperationalError.
+            # Wait here till it is released at which point this continues execution.
+            logger.info("Attempt to acquire lock (blocking) before updating licence %s", str(licence_id))
+            licence = Licence.objects.select_for_update().get(id=licence_id)
+
             send_licence(licence, action)
     except HMRCIntegrationException as e:
         logger.error("Error sending licence %s details to lite-hmrc: %s", str(licence_id), str(e))
@@ -49,5 +56,6 @@ def schedule_licence_details_to_lite_hmrc(licence_id, action):
         )
         return
 
-    logger.info("Scheduling task to %s licence %s details to lite-hmrc", action, str(licence_id))
+    logger.info("Scheduling task to %s licence %s details in lite-hmrc", action, licence.reference_code)
+
     send_licence_details_to_lite_hmrc.delay(licence_id, action)

api/licences/libraries/hmrc_integration_operations.py

@@ -33,9 +33,9 @@ class HMRCIntegrationException(APIException):
 
 
 def send_licence(licence: Licence, action: str):
-    """Sends licence information to HMRC Integration"""
+    """Sends licence information to lite-hmrc"""
 
-    logging.info(f"Sending licence '{licence.id}', action '{action}' to HMRC Integration")
+    logging.info("Sending licence %s with action %s to lite-hmrc", licence.reference_code, action)
 
     url = f"{settings.LITE_HMRC_INTEGRATION_URL}{SEND_LICENCE_ENDPOINT}"
     data = {"licence": HMRCIntegrationLicenceSerializer(licence).data}
@@ -46,15 +46,16 @@ def send_licence(licence: Licence, action: str):
 
     if response.status_code not in [status.HTTP_200_OK, status.HTTP_201_CREATED]:
         raise HMRCIntegrationException(
-            f"An unexpected response was received when sending licence '{licence.id}', action '{action}' to HMRC "
-            f"Integration -> status={response.status_code}, message={response.text}"
+            f"An unexpected response was received when sending licence '{licence.reference_code}', action '{action}' to lite-hmrc "
+            f"-> status={response.status_code}, message={response.text}"
         )
 
     if response.status_code == status.HTTP_201_CREATED:
+        logging.info("Record that new licence %s with action %s is sent to lite-hmrc", licence.reference_code, action)
         licence.hmrc_integration_sent_at = timezone.now()
         licence.save()
 
-    logging.info(f"Successfully sent licence '{licence.id}', action '{action}' to HMRC Integration")
+    logging.info("Successfully sent licence %s with action %s to lite-hmrc", licence.reference_code, action)
 
 
 def get_mail_status(licence: Licence):

api/licences/tests/test_api_to_hmrc_integration.py

@@ -380,8 +380,8 @@ def test_send_licence_failure(self, serializer, requests_post):
         requests_post.assert_called_once()
         self.assertEqual(
             str(error.exception),
-            f"An unexpected response was received when sending licence '{self.standard_licence.id}', "
-            f"action '{self.hmrc_integration_status}' to HMRC Integration -> status=400, message=Bad request",
+            f"An unexpected response was received when sending licence '{self.standard_licence.reference_code}', "
+            f"action '{self.hmrc_integration_status}' to lite-hmrc -> status=400, message=Bad request",
         )
         self.assertIsNone(self.standard_licence.hmrc_integration_sent_at)