From 1cfd19fb6a0e2c01629453cb03ef4b86e4bf9881 Mon Sep 17 00:00:00 2001 From: David McDonald Date: Mon, 18 Jan 2021 16:25:40 +0000 Subject: [PATCH 1/2] Reorder tests So all tests related to sms sending is done first and then all email sending task tests happen after --- tests/app/celery/test_provider_tasks.py | 63 +++++++++++++------------ 1 file changed, 32 insertions(+), 31 deletions(-) diff --git a/tests/app/celery/test_provider_tasks.py b/tests/app/celery/test_provider_tasks.py index ea30f950a..3507dc48a 100644 --- a/tests/app/celery/test_provider_tasks.py +++ b/tests/app/celery/test_provider_tasks.py @@ -46,19 +46,6 @@ def test_should_call_send_email_to_provider_from_deliver_email_task( app.delivery.send_to_providers.send_email_to_provider.assert_called_with(sample_notification) -def test_should_add_to_retry_queue_if_notification_not_found_in_deliver_email_task(mocker): - mocker.patch('app.delivery.send_to_providers.send_email_to_provider') - mocker.patch('app.celery.provider_tasks.deliver_email.retry') - - notification_id = app.create_uuid() - - deliver_email(notification_id) - app.delivery.send_to_providers.send_email_to_provider.assert_not_called() - app.celery.provider_tasks.deliver_email.retry.assert_called_with(queue="retry-tasks") - - -# DO THESE FOR THE 4 TYPES OF TASK - def test_should_go_into_technical_error_if_exceeds_retries_on_deliver_sms_task(sample_notification, mocker): mocker.patch('app.delivery.send_to_providers.send_sms_to_provider', side_effect=Exception("EXPECTED")) mocker.patch('app.celery.provider_tasks.deliver_sms.retry', side_effect=MaxRetriesExceededError()) @@ -72,6 +59,38 @@ def test_should_go_into_technical_error_if_exceeds_retries_on_deliver_sms_task(s assert sample_notification.status == 'technical-failure' +def test_send_sms_should_not_switch_providers_on_non_provider_failure( + sample_notification, + mocker +): + mocker.patch( + 'app.delivery.send_to_providers.send_sms_to_provider', + side_effect=Exception("Non Provider Exception") + ) + mock_dao_reduce_sms_provider_priority = mocker.patch( + 'app.delivery.send_to_providers.dao_reduce_sms_provider_priority' + ) + mocker.patch('app.celery.provider_tasks.deliver_sms.retry') + + deliver_sms(sample_notification.id) + + assert mock_dao_reduce_sms_provider_priority.called is False + + +# end of deliver_sms task tests, now deliver_email task tests + + +def test_should_add_to_retry_queue_if_notification_not_found_in_deliver_email_task(mocker): + mocker.patch('app.delivery.send_to_providers.send_email_to_provider') + mocker.patch('app.celery.provider_tasks.deliver_email.retry') + + notification_id = app.create_uuid() + + deliver_email(notification_id) + app.delivery.send_to_providers.send_email_to_provider.assert_not_called() + app.celery.provider_tasks.deliver_email.retry.assert_called_with(queue="retry-tasks") + + @pytest.mark.parametrize( 'exception_class', [ Exception(), @@ -149,21 +168,3 @@ def test_if_ses_send_rate_throttle_then_should_retry_and_log_warning(sample_noti assert sample_notification.status == 'created' assert not mock_logger_exception.called assert mock_logger_warning.called - - -def test_send_sms_should_not_switch_providers_on_non_provider_failure( - sample_notification, - mocker -): - mocker.patch( - 'app.delivery.send_to_providers.send_sms_to_provider', - side_effect=Exception("Non Provider Exception") - ) - mock_dao_reduce_sms_provider_priority = mocker.patch( - 'app.delivery.send_to_providers.dao_reduce_sms_provider_priority' - ) - mocker.patch('app.celery.provider_tasks.deliver_sms.retry') - - deliver_sms(sample_notification.id) - - assert mock_dao_reduce_sms_provider_priority.called is False From ac6837cde526fd6fe3d71fc768afca36ad17f32b Mon Sep 17 00:00:00 2001 From: David McDonald Date: Mon, 18 Jan 2021 15:43:50 +0000 Subject: [PATCH 2/2] Downgrade exception to warning for provider API call When we send an HTTP request to our SMS providers, there is a chance we get a 5xx status code back from them. Currently we log this as two different exception level logs. If a provider has a funny few minutes, we could end up with hundreds of exceptions thrown and pagerduty waking someone up in the middle of the night. These problems tend to pretty quickly fix themselves as we balance traffic from one SMS to the other SMS provider within 5 minutes. By downgrading both exceptions to warning in the case of a `SmsClientResponseException`, we will reduce the change of waking us up in the middle of the night for no reason. If the error is not a `SmsClientResponseException`, then we will still log at the exception level as before as this is more unexpected and we may want to be alerted sooner. What we still want to happen though is that let's say both SMS providers went down at the same time for 1 hour. We don't want our tasks to just sit there, retrying every 5 minutes for the whole time without us being aware (so we can at least raise a statuspage update). Luckily we will still be alerted because our smoke tests will fail after 10 minutes and raise a p1: https://github.com/alphagov/notifications-functional-tests/blob/master/tests/functional/staging_and_prod/notify_api/test_notify_api_sms.py#L21 --- app/celery/provider_tasks.py | 11 +++- app/clients/sms/firetext.py | 2 +- app/clients/sms/mmg.py | 2 +- tests/app/celery/test_provider_tasks.py | 75 +++++++++++++++++-------- 4 files changed, 63 insertions(+), 27 deletions(-) diff --git a/app/celery/provider_tasks.py b/app/celery/provider_tasks.py index 65878f1f6..60c01d201 100644 --- a/app/celery/provider_tasks.py +++ b/app/celery/provider_tasks.py @@ -6,6 +6,7 @@ from app import notify_celery from app.config import QueueNames from app.clients.email import EmailClientNonRetryableException from app.clients.email.aws_ses import AwsSesClientThrottlingSendRateException +from app.clients.sms import SmsClientResponseException from app.dao import notifications_dao from app.dao.notifications_dao import update_notification_status_by_id from app.delivery import send_to_providers @@ -22,11 +23,17 @@ def deliver_sms(self, notification_id): if not notification: raise NoResultFound() send_to_providers.send_sms_to_provider(notification) - except Exception: - try: + except Exception as e: + if isinstance(e, SmsClientResponseException): + current_app.logger.warning( + "SMS notification delivery for id: {} failed".format(notification_id) + ) + else: current_app.logger.exception( "SMS notification delivery for id: {} failed".format(notification_id) ) + + try: if self.request.retries == 0: self.retry(queue=QueueNames.RETRY, countdown=0) else: diff --git a/app/clients/sms/firetext.py b/app/clients/sms/firetext.py index a8b803613..d659f44f1 100644 --- a/app/clients/sms/firetext.py +++ b/app/clients/sms/firetext.py @@ -88,7 +88,7 @@ class FiretextClient(SmsClient): self.statsd_client.incr("clients.firetext.success") else: self.statsd_client.incr("clients.firetext.error") - self.current_app.logger.error(log_message) + self.current_app.logger.warning(log_message) def send_sms(self, to, content, reference, sender=None): diff --git a/app/clients/sms/mmg.py b/app/clients/sms/mmg.py index 752ff7792..57c43a037 100644 --- a/app/clients/sms/mmg.py +++ b/app/clients/sms/mmg.py @@ -90,7 +90,7 @@ class MMGClient(SmsClient): self.statsd_client.incr("clients.mmg.success") else: self.statsd_client.incr("clients.mmg.error") - self.current_app.logger.error(log_message) + self.current_app.logger.warning(log_message) def get_name(self): return self.name diff --git a/tests/app/celery/test_provider_tasks.py b/tests/app/celery/test_provider_tasks.py index 3507dc48a..ad024e045 100644 --- a/tests/app/celery/test_provider_tasks.py +++ b/tests/app/celery/test_provider_tasks.py @@ -5,6 +5,7 @@ from celery.exceptions import MaxRetriesExceededError import app from app.celery import provider_tasks from app.celery.provider_tasks import deliver_sms, deliver_email +from app.clients.sms import SmsClientResponseException from app.clients.email import EmailClientNonRetryableException from app.clients.email.aws_ses import AwsSesClientException, AwsSesClientThrottlingSendRateException from app.exceptions import NotificationTechnicalFailureException @@ -37,28 +38,6 @@ def test_should_add_to_retry_queue_if_notification_not_found_in_deliver_sms_task app.celery.provider_tasks.deliver_sms.retry.assert_called_with(queue="retry-tasks", countdown=0) -def test_should_call_send_email_to_provider_from_deliver_email_task( - sample_notification, - mocker): - mocker.patch('app.delivery.send_to_providers.send_email_to_provider') - - deliver_email(sample_notification.id) - app.delivery.send_to_providers.send_email_to_provider.assert_called_with(sample_notification) - - -def test_should_go_into_technical_error_if_exceeds_retries_on_deliver_sms_task(sample_notification, mocker): - mocker.patch('app.delivery.send_to_providers.send_sms_to_provider', side_effect=Exception("EXPECTED")) - mocker.patch('app.celery.provider_tasks.deliver_sms.retry', side_effect=MaxRetriesExceededError()) - - with pytest.raises(NotificationTechnicalFailureException) as e: - deliver_sms(sample_notification.id) - assert str(sample_notification.id) in str(e.value) - - provider_tasks.deliver_sms.retry.assert_called_with(queue="retry-tasks", countdown=0) - - assert sample_notification.status == 'technical-failure' - - def test_send_sms_should_not_switch_providers_on_non_provider_failure( sample_notification, mocker @@ -77,9 +56,59 @@ def test_send_sms_should_not_switch_providers_on_non_provider_failure( assert mock_dao_reduce_sms_provider_priority.called is False +def test_should_retry_and_log_warning_if_SmsClientResponseException_for_deliver_sms_task(sample_notification, mocker): + mocker.patch('app.delivery.send_to_providers.send_sms_to_provider', side_effect=SmsClientResponseException("something went wrong")) + mocker.patch('app.celery.provider_tasks.deliver_sms.retry') + mock_logger_warning = mocker.patch('app.celery.tasks.current_app.logger.warning') + + deliver_sms(sample_notification.id) + + assert provider_tasks.deliver_sms.retry.called is True + assert sample_notification.status == 'created' + assert mock_logger_warning.called + + +def test_should_retry_and_log_exception_for_non_SmsClientResponseException_exceptions_for_deliver_sms_task( + sample_notification, mocker +): + mocker.patch('app.delivery.send_to_providers.send_sms_to_provider', side_effect=Exception("something went wrong")) + mocker.patch('app.celery.provider_tasks.deliver_sms.retry') + mock_logger_exception = mocker.patch('app.celery.tasks.current_app.logger.exception') + + deliver_sms(sample_notification.id) + + assert provider_tasks.deliver_sms.retry.called is True + assert sample_notification.status == 'created' + assert mock_logger_exception.called + + +def test_should_go_into_technical_error_if_exceeds_retries_on_deliver_sms_task(sample_notification, mocker): + mocker.patch('app.delivery.send_to_providers.send_sms_to_provider', side_effect=Exception("EXPECTED")) + mocker.patch('app.celery.provider_tasks.deliver_sms.retry', side_effect=MaxRetriesExceededError()) + mock_logger_exception = mocker.patch('app.celery.tasks.current_app.logger.exception') + + with pytest.raises(NotificationTechnicalFailureException) as e: + deliver_sms(sample_notification.id) + assert str(sample_notification.id) in str(e.value) + + provider_tasks.deliver_sms.retry.assert_called_with(queue="retry-tasks", countdown=0) + + assert sample_notification.status == 'technical-failure' + assert mock_logger_exception.called + + # end of deliver_sms task tests, now deliver_email task tests +def test_should_call_send_email_to_provider_from_deliver_email_task( + sample_notification, + mocker): + mocker.patch('app.delivery.send_to_providers.send_email_to_provider') + + deliver_email(sample_notification.id) + app.delivery.send_to_providers.send_email_to_provider.assert_called_with(sample_notification) + + def test_should_add_to_retry_queue_if_notification_not_found_in_deliver_email_task(mocker): mocker.patch('app.delivery.send_to_providers.send_email_to_provider') mocker.patch('app.celery.provider_tasks.deliver_email.retry') @@ -125,7 +154,7 @@ def test_should_technical_error_and_not_retry_if_EmailClientNonRetryableExceptio assert sample_notification.status == 'technical-failure' -def test_should_retry_and_log_exception(sample_notification, mocker): +def test_should_retry_and_log_exception_for_deliver_email_task(sample_notification, mocker): error_response = { 'Error': { 'Code': 'SomeError',