code review feedback

app/celery/provider_tasks.py

@@ -1,4 +1,5 @@
 from datetime import datetime, timedelta
+from time import time
 from zoneinfo import ZoneInfo
 
 from flask import current_app
@@ -21,7 +22,7 @@ from app.models import (
 
 
 @notify_celery.task(bind=True, name="check_sms_delivery_receipt", max_retries=48, default_retry_delay=300)
-def check_sms_delivery_receipt(self, message_id, notification_id):
+def check_sms_delivery_receipt(self, message_id, notification_id, sent_at):
     """
     This is called after deliver_sms to check the status of the message. This uses the same number of
     retries and the same delay period as deliver_sms.  In addition, this fires five minutes after
@@ -31,17 +32,20 @@ def check_sms_delivery_receipt(self, message_id, notification_id):
     failure appears in the cloudwatch logs, so this should keep retrying until the log appears, or until
     we run out of retries.
     """
-    status, provider_response = aws_cloudwatch_client.check_sms(message_id, notification_id)
+    status, provider_response = aws_cloudwatch_client.check_sms(message_id, notification_id, sent_at)
     if status == 'success':
         status = NOTIFICATION_SENT
     else:
         status = NOTIFICATION_FAILED
     update_notification_status_by_id(notification_id, status, provider_response=provider_response)
+    current_app.logger.info(f"Updated notification {notification_id} with response '{provider_response}'")
 
 
 @notify_celery.task(bind=True, name="deliver_sms", max_retries=48, default_retry_delay=300)
 def deliver_sms(self, notification_id):
     try:
+        # Get the time we are doing the sending, to minimize the time period we need to check over for receipt
+        now = round(time() * 1000)
         current_app.logger.info("Start sending SMS for notification id: {}".format(notification_id))
         notification = notifications_dao.get_notification_by_id(notification_id)
         if not notification:
@@ -51,7 +55,7 @@ def deliver_sms(self, notification_id):
         # will be ignored and it will fire immediately (although this probably only affects developer testing)
         my_eta = datetime.now(ZoneInfo('US/Eastern')) + timedelta(seconds=300)
         check_sms_delivery_receipt.apply_async(
-            [message_id, notification_id],
+            [message_id, notification_id, now],
             eta=my_eta,
             queue=QueueNames.CHECK_SMS
         )

app/clients/cloudwatch/aws_cloudwatch.py

@@ -28,12 +28,11 @@ class AwsCloudwatchClient(Client):
     def name(self):
         return 'cloudwatch'
 
-    def _get_all_logs(self, my_filter, log_group_name):
+    def _get_log(self, my_filter, log_group_name, sent_at):
 
-        # Check all events in the last 30 minutes
+        # Check all cloudwatch logs from the time the notification was sent (currently 5 minutes previously) until now
         now = round(time.time() * 1000)
-        beginning = now - 30 * 60 * 1000
+        beginning = sent_at
-
         next_token = None
         all_log_events = []
         while True:
@@ -54,12 +53,16 @@ class AwsCloudwatchClient(Client):
                 )
             log_events = response.get('events', [])
             all_log_events.extend(log_events)
+            if len(log_events) > 0:
+                # We found it
+                break
             next_token = response.get('nextToken')
             if not next_token:
                 break
         return all_log_events
 
-    def check_sms(self, message_id, notification_id):
+    def check_sms(self, message_id, notification_id, created_at):
+
         # TODO this clumsy approach to getting the account number will be fixed as part of notify-api #258
         account_number = cloud_config.ses_domain_arn
         account_number = account_number.replace('arn:aws:ses:us-west-2:', '')
@@ -69,7 +72,7 @@ class AwsCloudwatchClient(Client):
         log_group_name = f'sns/us-west-2/{account_number}/DirectPublishToPhoneNumber'
         filter_pattern = '{$.notification.messageId="XXXXX"}'
         filter_pattern = filter_pattern.replace("XXXXX", message_id)
-        all_log_events = self._get_all_logs(filter_pattern, log_group_name)
+        all_log_events = self._get_log(filter_pattern, log_group_name, created_at)
 
         if all_log_events and len(all_log_events) > 0:
             event = all_log_events[0]
@@ -77,7 +80,7 @@ class AwsCloudwatchClient(Client):
             return "success", message['delivery']['providerResponse']
 
         log_group_name = f'sns/us-west-2/{account_number}/DirectPublishToPhoneNumber/Failure'
-        all_failed_events = self._get_all_logs(filter_pattern, log_group_name)
+        all_failed_events = self._get_log(filter_pattern, log_group_name, created_at)
         if all_failed_events and len(all_failed_events) > 0:
             event = all_failed_events[0]
             message = json.loads(event['message'])

tests/app/clients/test_aws_cloudwatch.py

@@ -58,7 +58,7 @@ def test_check_sms_success(notify_api, mocker):
     message_id = 'succeed'
     notification_id = 'ccc'
     with notify_api.app_context():
-        aws_cloudwatch_client.check_sms(message_id, notification_id)
+        aws_cloudwatch_client.check_sms(message_id, notification_id, 1000000000000)
 
     # We check the 'success' log group first and if we find the message_id, we are done, so there is only 1 call
     assert boto_mock.filter_log_events.call_count == 1
@@ -77,7 +77,7 @@ def test_check_sms_failure(notify_api, mocker):
     message_id = 'fail'
     notification_id = 'bbb'
     with notify_api.app_context():
-        aws_cloudwatch_client.check_sms(message_id, notification_id)
+        aws_cloudwatch_client.check_sms(message_id, notification_id, 1000000000000)
 
     # We check the 'success' log group and find nothing, so we then check the 'fail' log group -- two calls.
     assert boto_mock.filter_log_events.call_count == 2