From 1e72f97b17894b5bb75f122bf9232ee43b7ccfe2 Mon Sep 17 00:00:00 2001 From: Kenneth Kehl <@kkehl@flexion.us> Date: Tue, 9 May 2023 08:45:51 -0700 Subject: [PATCH] code review feedback --- app/celery/provider_tasks.py | 10 +++++++--- app/clients/cloudwatch/aws_cloudwatch.py | 17 ++++++++++------- tests/app/clients/test_aws_cloudwatch.py | 4 ++-- 3 files changed, 19 insertions(+), 12 deletions(-) diff --git a/app/celery/provider_tasks.py b/app/celery/provider_tasks.py index 1fe30c92c..01d826ba6 100644 --- a/app/celery/provider_tasks.py +++ b/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 ) diff --git a/app/clients/cloudwatch/aws_cloudwatch.py b/app/clients/cloudwatch/aws_cloudwatch.py index e3e351559..97de58219 100644 --- a/app/clients/cloudwatch/aws_cloudwatch.py +++ b/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']) diff --git a/tests/app/clients/test_aws_cloudwatch.py b/tests/app/clients/test_aws_cloudwatch.py index 38ca50243..5a54383b5 100644 --- a/tests/app/clients/test_aws_cloudwatch.py +++ b/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