From bd09c63ea97e719cd223e7680bd1015dda25b224 Mon Sep 17 00:00:00 2001 From: Kenneth Kehl <@kkehl@flexion.us> Date: Mon, 2 Oct 2023 14:09:50 -0700 Subject: [PATCH 1/5] notify-api-521 fix sms temporary failure message --- app/celery/provider_tasks.py | 30 ++++++++++++++++++------ app/clients/cloudwatch/aws_cloudwatch.py | 12 ++++++++-- app/models.py | 4 ++-- tests/app/celery/test_provider_tasks.py | 2 +- tests/app/test_model.py | 8 +++++-- 5 files changed, 42 insertions(+), 14 deletions(-) diff --git a/app/celery/provider_tasks.py b/app/celery/provider_tasks.py index 02b435990..d12ef05aa 100644 --- a/app/celery/provider_tasks.py +++ b/app/celery/provider_tasks.py @@ -1,6 +1,5 @@ import os from datetime import datetime, timedelta -from time import time from flask import current_app from sqlalchemy.orm.exc import NoResultFound @@ -21,6 +20,7 @@ from app.models import ( NOTIFICATION_DELIVERED, NOTIFICATION_FAILED, NOTIFICATION_TECHNICAL_FAILURE, + NOTIFICATION_TEMPORARY_FAILURE, ) # This is the amount of time to wait after sending an sms message before we check the aws logs and look for delivery @@ -49,9 +49,20 @@ def check_sms_delivery_receipt(self, message_id, notification_id, sent_at): status = "success" provider_response = "this is a fake successful localstack sms message" else: - status, provider_response = aws_cloudwatch_client.check_sms( - message_id, notification_id, sent_at - ) + try: + status, provider_response = aws_cloudwatch_client.check_sms( + message_id, notification_id, sent_at + ) + except NotificationTechnicalFailureException as ntfe: + provider_response = "Unable to find carrier response -- still looking" + status = "pending" + current_app.logger.info( + "UPDATING WITH TEMPORARY FAILURE AND GOING TO RETRY" + ) + update_notification_status_by_id( + notification_id, status, provider_response=provider_response + ) + raise self.retry(exc=ntfe) if status == "success": status = NOTIFICATION_DELIVERED @@ -80,8 +91,6 @@ def check_sms_delivery_receipt(self, message_id, notification_id, sent_at): ) 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) ) @@ -106,9 +115,15 @@ def deliver_sms(self, notification_id): seconds=DELIVERY_RECEIPT_DELAY_IN_SECONDS ) check_sms_delivery_receipt.apply_async( - [message_id, notification_id, now], eta=my_eta, queue=QueueNames.CHECK_SMS + [message_id, notification_id, notification.created_at], + eta=my_eta, + queue=QueueNames.CHECK_SMS, ) except Exception as e: + current_app.logger.info("TEMPORARY FAILURE!") + update_notification_status_by_id( + notification_id, NOTIFICATION_TEMPORARY_FAILURE + ) if isinstance(e, SmsClientResponseException): current_app.logger.warning( "SMS notification delivery for id: {} failed".format(notification_id), @@ -125,6 +140,7 @@ def deliver_sms(self, notification_id): else: self.retry(queue=QueueNames.RETRY) except self.MaxRetriesExceededError: + current_app.logger.info("PERMANENT FAILURE!") message = ( "RETRY FAILED: Max retries reached. The task send_sms_to_provider failed for notification {}. " "Notification has been updated to technical-failure".format( diff --git a/app/clients/cloudwatch/aws_cloudwatch.py b/app/clients/cloudwatch/aws_cloudwatch.py index aba9d54e0..a9c319776 100644 --- a/app/clients/cloudwatch/aws_cloudwatch.py +++ b/app/clients/cloudwatch/aws_cloudwatch.py @@ -2,12 +2,15 @@ import json import os import re import time +from datetime import datetime +from _datetime import timedelta from boto3 import client from flask import current_app from app.clients import AWS_CLIENT_CONFIG, Client from app.cloudfoundry_config import cloud_config +from app.exceptions import NotificationTechnicalFailureException class AwsCloudwatchClient(Client): @@ -89,6 +92,7 @@ class AwsCloudwatchClient(Client): # TODO this clumsy approach to getting the account number will be fixed as part of notify-api #258 account_number = self._extract_account_number(cloud_config.ses_domain_arn) + time_now = datetime.utcnow() log_group_name = f"sns/{region}/{account_number[4]}/DirectPublishToPhoneNumber" current_app.logger.info( f"Log group name: {log_group_name} message id: {message_id}" @@ -105,7 +109,7 @@ class AwsCloudwatchClient(Client): log_group_name = ( f"sns/{region}/{account_number[4]}/DirectPublishToPhoneNumber/Failure" ) - # current_app.logger.info(f"Failure log group name: {log_group_name}") + current_app.logger.info(f"Failure log group name: {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: current_app.logger.info("SHOULD RETURN FAILED BECAUSE WE FOUND A FAILURE") @@ -114,6 +118,10 @@ class AwsCloudwatchClient(Client): current_app.logger.info(f"MESSAGE {message}") return "failure", message["delivery"]["providerResponse"] - raise Exception( + if time_now > (created_at + timedelta(hours=3)): + # see app/models.py Notification. This message corresponds to "permanent-failure", + # but we are copy/pasting here to avoid circular imports. + return "failure", "Unable to find carrier response." + raise NotificationTechnicalFailureException( f"No event found for message_id {message_id} notification_id {notification_id}" ) diff --git a/app/models.py b/app/models.py index f4649ce7c..edc62d0bb 100644 --- a/app/models.py +++ b/app/models.py @@ -1727,8 +1727,8 @@ class Notification(db.Model): "sms": { "failed": "Failed", "technical-failure": "Technical failure", - "temporary-failure": "Phone not accepting messages right now", - "permanent-failure": "Phone number doesn’t exist", + "temporary-failure": "Unable to find carrier response -- still looking", + "permanent-failure": "Unable to find carrier response.", "delivered": "Delivered", "sending": "Sending", "created": "Sending", diff --git a/tests/app/celery/test_provider_tasks.py b/tests/app/celery/test_provider_tasks.py index 83e9a058d..532c19e3f 100644 --- a/tests/app/celery/test_provider_tasks.py +++ b/tests/app/celery/test_provider_tasks.py @@ -105,7 +105,7 @@ def test_should_go_into_technical_error_if_exceeds_retries_on_deliver_sms_task( queue="retry-tasks", countdown=0 ) - assert sample_notification.status == "technical-failure" + assert sample_notification.status == "temporary-failure" assert mock_logger_exception.called diff --git a/tests/app/test_model.py b/tests/app/test_model.py index d7f8d8e50..20a7763cb 100644 --- a/tests/app/test_model.py +++ b/tests/app/test_model.py @@ -139,8 +139,12 @@ def test_notification_for_csv_returns_correct_job_row_number(sample_job): ("email", "technical-failure", "Technical failure"), ("email", "temporary-failure", "Inbox not accepting messages right now"), ("email", "permanent-failure", "Email address doesn’t exist"), - ("sms", "temporary-failure", "Phone not accepting messages right now"), - ("sms", "permanent-failure", "Phone number doesn’t exist"), + ( + "sms", + "temporary-failure", + "Unable to find carrier response -- still looking", + ), + ("sms", "permanent-failure", "Unable to find carrier response."), ("sms", "sent", "Sent internationally"), ], ) From 2487aeb6578976f361914dffea3b690e422e4cfe Mon Sep 17 00:00:00 2001 From: Kenneth Kehl <@kkehl@flexion.us> Date: Mon, 2 Oct 2023 14:13:25 -0700 Subject: [PATCH 2/5] remove debugging --- app/celery/provider_tasks.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/app/celery/provider_tasks.py b/app/celery/provider_tasks.py index d12ef05aa..dae150ee6 100644 --- a/app/celery/provider_tasks.py +++ b/app/celery/provider_tasks.py @@ -56,9 +56,6 @@ def check_sms_delivery_receipt(self, message_id, notification_id, sent_at): except NotificationTechnicalFailureException as ntfe: provider_response = "Unable to find carrier response -- still looking" status = "pending" - current_app.logger.info( - "UPDATING WITH TEMPORARY FAILURE AND GOING TO RETRY" - ) update_notification_status_by_id( notification_id, status, provider_response=provider_response ) @@ -120,7 +117,6 @@ def deliver_sms(self, notification_id): queue=QueueNames.CHECK_SMS, ) except Exception as e: - current_app.logger.info("TEMPORARY FAILURE!") update_notification_status_by_id( notification_id, NOTIFICATION_TEMPORARY_FAILURE ) @@ -140,7 +136,6 @@ def deliver_sms(self, notification_id): else: self.retry(queue=QueueNames.RETRY) except self.MaxRetriesExceededError: - current_app.logger.info("PERMANENT FAILURE!") message = ( "RETRY FAILED: Max retries reached. The task send_sms_to_provider failed for notification {}. " "Notification has been updated to technical-failure".format( From 6af998a08057cd159331cead02fbbfeffd6ff5d3 Mon Sep 17 00:00:00 2001 From: Kenneth Kehl <@kkehl@flexion.us> Date: Tue, 3 Oct 2023 07:31:24 -0700 Subject: [PATCH 3/5] notify-api-521 code review feedback and fix code coverage --- app/clients/cloudwatch/aws_cloudwatch.py | 3 +-- app/notifications/receive_notifications.py | 16 +++++----------- 2 files changed, 6 insertions(+), 13 deletions(-) diff --git a/app/clients/cloudwatch/aws_cloudwatch.py b/app/clients/cloudwatch/aws_cloudwatch.py index a9c319776..e4da17645 100644 --- a/app/clients/cloudwatch/aws_cloudwatch.py +++ b/app/clients/cloudwatch/aws_cloudwatch.py @@ -2,9 +2,8 @@ import json import os import re import time -from datetime import datetime +from datetime import datetime, timedelta -from _datetime import timedelta from boto3 import client from flask import current_app diff --git a/app/notifications/receive_notifications.py b/app/notifications/receive_notifications.py index 694d7eb1b..2d9a064ab 100644 --- a/app/notifications/receive_notifications.py +++ b/app/notifications/receive_notifications.py @@ -54,19 +54,13 @@ def receive_sns_sms(): ) return jsonify(result="success", message="SMS-SNS callback succeeded"), 200 - content = message.get("messageBody") - from_number = message.get("originationNumber") - provider_ref = message.get("inboundMessageId") - date_received = post_data.get("Timestamp") - provider_name = "sns" - inbound = create_inbound_sms_object( service, - content=content, - from_number=from_number, - provider_ref=provider_ref, - date_received=date_received, - provider_name=provider_name, + content=message.get("messageBody"), + from_number=message.get("originationNumber"), + provider_ref=message.get("inboundMessageId"), + date_received=post_data.get("Timestamp"), + provider_name="sns", ) tasks.send_inbound_sms_to_service.apply_async( From ef64bd424a814dab107994ea237257ddfd8fc00e Mon Sep 17 00:00:00 2001 From: Kenneth Kehl <@kkehl@flexion.us> Date: Tue, 3 Oct 2023 07:52:20 -0700 Subject: [PATCH 4/5] fix time passed to boto3 --- app/clients/cloudwatch/aws_cloudwatch.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/app/clients/cloudwatch/aws_cloudwatch.py b/app/clients/cloudwatch/aws_cloudwatch.py index e4da17645..6f91ed817 100644 --- a/app/clients/cloudwatch/aws_cloudwatch.py +++ b/app/clients/cloudwatch/aws_cloudwatch.py @@ -61,14 +61,14 @@ class AwsCloudwatchClient(Client): logGroupName=log_group_name, filterPattern=my_filter, nextToken=next_token, - startTime=beginning, + startTime=int(beginning.timestamp() * 1000), endTime=now, ) else: response = self._client.filter_log_events( logGroupName=log_group_name, filterPattern=my_filter, - startTime=beginning, + startTime=int(beginning.timestamp() * 1000), endTime=now, ) log_events = response.get("events", []) From 679dee8123d2015659f40a0f08f4a42df742c774 Mon Sep 17 00:00:00 2001 From: Kenneth Kehl <@kkehl@flexion.us> Date: Tue, 3 Oct 2023 08:00:59 -0700 Subject: [PATCH 5/5] fix tests --- tests/app/clients/test_aws_cloudwatch.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/tests/app/clients/test_aws_cloudwatch.py b/tests/app/clients/test_aws_cloudwatch.py index 5f25f1d9f..6662d2edb 100644 --- a/tests/app/clients/test_aws_cloudwatch.py +++ b/tests/app/clients/test_aws_cloudwatch.py @@ -1,4 +1,6 @@ # import pytest +from datetime import datetime + from flask import current_app from app import aws_cloudwatch_client @@ -61,8 +63,9 @@ def test_check_sms_success(notify_api, mocker): message_id = "succeed" notification_id = "ccc" + created_at = datetime.utcnow() with notify_api.app_context(): - aws_cloudwatch_client.check_sms(message_id, notification_id, 1000000000000) + aws_cloudwatch_client.check_sms(message_id, notification_id, created_at) # 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 @@ -82,8 +85,9 @@ def test_check_sms_failure(notify_api, mocker): ) message_id = "fail" notification_id = "bbb" + created_at = datetime.utcnow() with notify_api.app_context(): - aws_cloudwatch_client.check_sms(message_id, notification_id, 1000000000000) + aws_cloudwatch_client.check_sms(message_id, notification_id, created_at) # 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