diff --git a/app/celery/provider_tasks.py b/app/celery/provider_tasks.py index 02b435990..dae150ee6 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,17 @@ 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" + 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 +88,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 +112,14 @@ 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: + 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), diff --git a/app/clients/cloudwatch/aws_cloudwatch.py b/app/clients/cloudwatch/aws_cloudwatch.py index aba9d54e0..6f91ed817 100644 --- a/app/clients/cloudwatch/aws_cloudwatch.py +++ b/app/clients/cloudwatch/aws_cloudwatch.py @@ -2,12 +2,14 @@ import json import os import re import time +from datetime import datetime, 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): @@ -59,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", []) @@ -89,6 +91,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 +108,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 +117,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/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( 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/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 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"), ], )