Update logging for provider tasks.

Move the info message before the fetch.
Include the exception in the log message.

app/celery/provider_tasks.py

@@ -22,15 +22,15 @@ def worker_process_shutdown(sender, signal, pid, exitcode):
 @statsd(namespace="tasks")
 def deliver_sms(self, notification_id):
     try:
+        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:
             raise NoResultFound()
-        current_app.logger.info("Start sending SMS for notification id: {}".format(notification_id))
         send_to_providers.send_sms_to_provider(notification)
     except Exception as e:
         try:
             current_app.logger.exception(
-                "SMS notification delivery for id: {} failed".format(notification_id)
+                "SMS notification delivery for id: {} failed".format(notification_id), e
             )
             self.retry(queue=QueueNames.RETRY)
         except self.MaxRetriesExceededError:
@@ -44,10 +44,10 @@ def deliver_sms(self, notification_id):
 @statsd(namespace="tasks")
 def deliver_email(self, notification_id):
     try:
+        current_app.logger.info("Start sending email for notification id: {}".format(notification_id))
         notification = notifications_dao.get_notification_by_id(notification_id)
         if not notification:
             raise NoResultFound()
-        current_app.logger.info("Start sending email for notification id: {}".format(notification_id))
         send_to_providers.send_email_to_provider(notification)
     except InvalidEmailError as e:
         current_app.logger.exception(e)
@@ -55,7 +55,7 @@ def deliver_email(self, notification_id):
     except Exception as e:
         try:
             current_app.logger.exception(
-                "RETRY: Email notification {} failed".format(notification_id)
+                "RETRY: Email notification {} failed".format(notification_id), e
             )
             self.retry(queue=QueueNames.RETRY)
         except self.MaxRetriesExceededError:

tests/app/celery/test_provider_tasks.py

@@ -1,10 +1,12 @@
 import pytest
+from botocore.exceptions import ClientError
 from celery.exceptions import MaxRetriesExceededError
 from notifications_utils.recipients import InvalidEmailError
 
 import app
 from app.celery import provider_tasks
 from app.celery.provider_tasks import deliver_sms, deliver_email
+from app.clients.email.aws_ses import AwsSesClientException
 from app.exceptions import NotificationTechnicalFailureException
 
 
@@ -92,6 +94,24 @@ def test_should_technical_error_and_not_retry_if_invalid_email(sample_notificati
     assert sample_notification.status == 'technical-failure'
 
 
+def test_should_retry_and_log_exception(sample_notification, mocker):
+    error_response = {
+        'Error': {
+            'Code': 'SomeError',
+            'Message': 'some error message from amazon',
+            'Type': 'Sender'
+        }
+    }
+    ex = ClientError(error_response=error_response, operation_name='opname')
+    mocker.patch('app.delivery.send_to_providers.send_email_to_provider', side_effect=AwsSesClientException(str(ex)))
+    mocker.patch('app.celery.provider_tasks.deliver_email.retry')
+
+    deliver_email(sample_notification.id)
+
+    assert provider_tasks.deliver_email.retry.called is True
+    assert sample_notification.status == 'created'
+
+
 def test_send_sms_should_switch_providers_on_provider_failure(sample_notification, mocker):
     provider_to_use = mocker.patch('app.delivery.send_to_providers.provider_to_use')
     provider_to_use.return_value.send_sms.side_effect = Exception('Error')