From f96ba5361af1a09002f95b082e2063fbd220b700 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Wed, 24 Nov 2021 13:47:48 +0000 Subject: [PATCH 01/13] Add new task to alert about created email / sms This will log an error when email or SMS notifications have been stuck in 'created' for too long - normally they should be 'sending' in seconds, noting that we have a goal of < 10s wait time for most notifications being processed our platform. In the next commits we'll decouple similar functionality from the existing 'timeout-sending-notifications' task. --- app/celery/scheduled_tasks.py | 14 ++++++++++ app/config.py | 6 ++++ app/dao/notifications_dao.py | 10 +++++++ tests/app/celery/test_scheduled_tasks.py | 19 +++++++++++++ .../notification_dao/test_notification_dao.py | 28 +++++++++++++++++++ 5 files changed, 77 insertions(+) diff --git a/app/celery/scheduled_tasks.py b/app/celery/scheduled_tasks.py index 968a4231d..804194cb5 100644 --- a/app/celery/scheduled_tasks.py +++ b/app/celery/scheduled_tasks.py @@ -30,6 +30,7 @@ from app.dao.jobs_dao import ( find_missing_row_for_job, ) from app.dao.notifications_dao import ( + dao_check_notifications_still_in_created, dao_old_letters_with_created_status, dao_precompiled_letters_still_pending_virus_check, is_delivery_slow_for_providers, @@ -118,6 +119,19 @@ def switch_current_sms_provider_on_slow_delivery(): dao_reduce_sms_provider_priority(provider_name, time_threshold=timedelta(minutes=10)) +@notify_celery.task(name='raise-alert-if-email-sms-still-in-created') +def raise_alert_if_email_sms_still_in_created(): + alert_above_age = current_app.config.get('CREATED_NOTIFICATIONS_ALERT_AGE') + still_in_created = dao_check_notifications_still_in_created(alert_above_age) + message = f"{still_in_created} notifications are still in 'created'." + + if still_in_created == 0: + current_app.logger.info(message) + return + + current_app.logger.error(message) + + @notify_celery.task(name='tend-providers-back-to-middle') def tend_providers_back_to_middle(): dao_adjust_provider_priority_back_to_resting_points() diff --git a/app/config.py b/app/config.py index ab5a08b27..d953e1433 100644 --- a/app/config.py +++ b/app/config.py @@ -310,6 +310,11 @@ class Config(object): 'schedule': crontab(hour=15, minute=30), 'options': {'queue': QueueNames.PERIODIC} }, + 'raise-alert-if-email-sms-still-in-created': { + 'task': 'raise-alert-if-email-sms-still-in-created', + 'schedule': crontab(minute=30), + 'options': {'queue': QueueNames.PERIODIC}, + }, # The collate-letter-pdf does assume it is called in an hour that BST does not make a # difference to the truncate date which translates to the filename to process 'collate-letter-pdfs-to-be-sent': { @@ -355,6 +360,7 @@ class Config(object): STATSD_ENABLED = bool(STATSD_HOST) SENDING_NOTIFICATIONS_TIMEOUT_PERIOD = 259200 # 3 days + CREATED_NOTIFICATIONS_ALERT_AGE = 3600 # 1 hour SIMULATED_EMAIL_ADDRESSES = ( 'simulate-delivered@notifications.service.gov.uk', diff --git a/app/dao/notifications_dao.py b/app/dao/notifications_dao.py index 44f2bddee..1a823c5dd 100644 --- a/app/dao/notifications_dao.py +++ b/app/dao/notifications_dao.py @@ -512,6 +512,16 @@ def _timeout_notifications(current_statuses, new_status, timeout_start, updated_ return notifications +def dao_check_notifications_still_in_created(minimum_age_in_seconds): + min_created_at = datetime.utcnow() - timedelta(seconds=minimum_age_in_seconds) + + return Notification.query.filter( + Notification.created_at < min_created_at, + Notification.status == NOTIFICATION_CREATED, + Notification.notification_type.in_([SMS_TYPE, EMAIL_TYPE]) + ).count() + + def dao_timeout_notifications(timeout_period_in_seconds): """ Timeout SMS and email notifications by the following rules: diff --git a/tests/app/celery/test_scheduled_tasks.py b/tests/app/celery/test_scheduled_tasks.py index edd8cbeee..68ae6d073 100644 --- a/tests/app/celery/test_scheduled_tasks.py +++ b/tests/app/celery/test_scheduled_tasks.py @@ -19,6 +19,7 @@ from app.celery.scheduled_tasks import ( check_job_status, delete_invitations, delete_verify_codes, + raise_alert_if_email_sms_still_in_created, remove_yesterdays_planned_tests_on_govuk_alerts, replay_created_notifications, run_scheduled_jobs, @@ -108,6 +109,24 @@ def test_should_update_all_scheduled_jobs_and_put_on_queue(sample_template, mock ]) +def test_raise_alert_if_email_sms_still_in_created(notify_api, mocker): + mock_check = mocker.patch('app.celery.scheduled_tasks.dao_check_notifications_still_in_created') + mock_logger = mocker.patch('app.celery.scheduled_tasks.current_app.logger') + + mock_check.return_value = 0 + raise_alert_if_email_sms_still_in_created() + mock_logger.info.assert_called_once_with("0 notifications are still in 'created'.") + + assert mock_check.called_once_with( + notify_api.config['CREATED_NOTIFICATIONS_ALERT_AGE'] + ) + + # try again with something to alert about + mock_check.return_value = 1 + raise_alert_if_email_sms_still_in_created() + mock_logger.error.assert_called_once_with("1 notifications are still in 'created'.") + + @freeze_time('2017-05-01 14:00:00') def test_switch_current_sms_provider_on_slow_delivery_switches_when_one_provider_is_slow( mocker, diff --git a/tests/app/dao/notification_dao/test_notification_dao.py b/tests/app/dao/notification_dao/test_notification_dao.py index a237bf5fd..25e4ca261 100644 --- a/tests/app/dao/notification_dao/test_notification_dao.py +++ b/tests/app/dao/notification_dao/test_notification_dao.py @@ -8,6 +8,7 @@ from sqlalchemy.exc import IntegrityError, SQLAlchemyError from sqlalchemy.orm.exc import NoResultFound from app.dao.notifications_dao import ( + dao_check_notifications_still_in_created, dao_create_notification, dao_delete_notifications_by_id, dao_get_last_notification_added_for_job_id, @@ -664,6 +665,33 @@ def _notification_json(sample_template, job_id=None, id=None, status=None): return data +def test_dao_check_notifications_still_in_created( + sample_template, + sample_email_template, + sample_letter_template +): + with freeze_time(datetime.utcnow() - timedelta(minutes=2)): + # old sending notification (ignored) + create_notification(sample_template, status='sending') + # old letter notification (ignored) + create_notification(sample_letter_template, status='created') + + with freeze_time(datetime.utcnow() + timedelta(minutes=10)): + # new / future notification (ignored) + create_notification(sample_template, status='created') + + # first prove all the above notifications are ignored + assert dao_check_notifications_still_in_created(1) == 0 + + with freeze_time(datetime.utcnow() - timedelta(minutes=2)): + # now add old, eligible notifications + create_notification(sample_template, status='created') + create_notification(sample_email_template, status='created') + + # now prove the check only picks up on these ones + assert dao_check_notifications_still_in_created(1) == 2 + + def test_dao_timeout_notifications(sample_template): with freeze_time(datetime.utcnow() - timedelta(minutes=2)): created = create_notification(sample_template, status='created') From 2acc4ee67d2e3335bce89d0fa71e5ab85658ef23 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 17:02:57 +0000 Subject: [PATCH 02/13] Repurpose command to replay notification callbacks This is so we can use it to address issues highlighted by the new alert, if it's not possible to actually send the notifications e.g. if they are somehow 'invalid'. Previously this was added for a one-off use case [1]. This rewrites the task to operate on arbitrary notification IDs instead of client refs, which aren't always present for notifications we may want to send / replay callbacks for. Since the task may now need to work on notifications more than one service, I had to restructure it to cope with multiple callback APIs. Note that, in the test, I've chosen to do a chain of invocations and assertions, rather than duplicate a load of boilerplate or introduce funky parametrize flags for a service with/out a callback API. We'll refactor this in a later commit. [1]: https://github.com/alphagov/notifications-api/commit/e95740a6b517b4da7141087c19dbeb26e1c38df7 --- app/commands.py | 57 +++++++++++++++++--------------------- tests/app/test_commands.py | 48 ++++++++++++++++++++++++++++++-- 2 files changed, 72 insertions(+), 33 deletions(-) diff --git a/app/commands.py b/app/commands.py index 4edbce9d1..2cf43f8f6 100644 --- a/app/commands.py +++ b/app/commands.py @@ -284,42 +284,37 @@ def recreate_pdf_for_precompiled_or_uploaded_letter(notification_id): resanitise_pdf.apply_async([str(notification_id)], queue=QueueNames.LETTERS) -@notify_command(name='replay-service-callbacks') -@click.option('-f', '--file_name', required=True, - help="""Full path of the file to upload, file is a contains client references of +@notify_command(name='replay-callbacks') +@click.option('-f', '--file-name', required=True, + help="""Full path of the file to upload, containing IDs of notifications that need the status to be sent to the service.""") -@click.option('-s', '--service_id', required=True, - help="""The service that the callbacks are for""") -def replay_service_callbacks(file_name, service_id): - print("Start send service callbacks for service: ", service_id) - callback_api = get_service_delivery_status_callback_api_for_service(service_id=service_id) - if not callback_api: - print("Callback api was not found for service: {}".format(service_id)) - return - - errors = [] - notifications = [] +def replay_callbacks(file_name): + print("Replaying callbacks.") file = open(file_name) - for ref in file: + for id in [id.strip() for id in file]: try: - notification = Notification.query.filter_by(client_reference=ref.strip()).one() - notifications.append(notification) + notification = Notification.query.filter_by(id=id).one() + + callback_api = get_service_delivery_status_callback_api_for_service( + service_id=notification.service_id + ) + + if not callback_api: + print(f"Callback api was not found for notification: {id}.") + continue + + encrypted_status_update = create_delivery_status_callback_data( + notification, callback_api + ) + + send_delivery_status_to_service.apply_async( + [id, encrypted_status_update], queue=QueueNames.CALLBACKS + ) + + print(f"Created callback task for notification: {id}.") except NoResultFound: - errors.append("Reference: {} was not found in notifications.".format(ref)) - - for e in errors: - print(e) - if errors: - raise Exception("Some notifications for the given references were not found") - - for n in notifications: - encrypted_status_update = create_delivery_status_callback_data(n, callback_api) - send_delivery_status_to_service.apply_async([str(n.id), encrypted_status_update], - queue=QueueNames.CALLBACKS) - - print("Replay service status for service: {}. Sent {} notification status updates to the queue".format( - service_id, len(notifications))) + print(f"ID: {id} was not found in notifications.") def setup_commands(application): diff --git a/tests/app/test_commands.py b/tests/app/test_commands.py index dd8f1c15b..98f092a89 100644 --- a/tests/app/test_commands.py +++ b/tests/app/test_commands.py @@ -1,6 +1,9 @@ -from app.commands import local_dev_broadcast_permissions +import uuid + +from app.commands import local_dev_broadcast_permissions, replay_callbacks +from app.config import QueueNames from app.dao.services_dao import dao_add_user_to_service -from tests.app.db import create_user +from tests.app.db import create_service_callback_api, create_user def test_local_dev_broadcast_permissions( @@ -21,3 +24,44 @@ def test_local_dev_broadcast_permissions( assert len(user.get_permissions(sample_service.id)) == 0 assert len(user.get_permissions(sample_broadcast_service.id)) > 0 + + +def test_replay_callbacks( + mocker, + sample_service, + sample_notification, + tmpdir, + notify_api, +): + mock_apply = mocker.patch('app.commands.send_delivery_status_to_service.apply_async') + mock_update = mocker.patch('app.commands.create_delivery_status_callback_data') + mock_update.return_value = 'encrypted_status_update' + + file_path = tmpdir + 'callback_ids.txt' + missing_notification_id = uuid.uuid4() + + with open(file_path, 'w') as f: + f.write(str(sample_notification.id) + "\n") + f.write(str(missing_notification_id) + "\n") + + result = notify_api.test_cli_runner().invoke( + replay_callbacks, ['-f', file_path] + ) + + mock_apply.assert_not_called() + assert f'{missing_notification_id} was not found' in result.output + assert "Callback api was not found" in result.output + + # Now re-run with the callback API in place + create_service_callback_api(service=sample_service, bearer_token='foo') + + result = notify_api.test_cli_runner().invoke( + replay_callbacks, ['-f', file_path] + ) + + mock_apply.assert_called_once_with( + [str(sample_notification.id), 'encrypted_status_update'], + queue=QueueNames.CALLBACKS + ) + + assert result.exit_code == 0 From 031822921614cd62a4c176fbcb554d59ce7157e4 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 16:59:26 +0000 Subject: [PATCH 03/13] Stop 'timing out' old 'created' notifications This is being replaced with a new alert and runbook [1]. It's not always appropriate to change the status to 'technical-failure', and the new alert means we'll act to fix the underlying issue promptly. We'll look at tidying up the remaining code in the next commits. [1]: https://github.com/alphagov/notifications-manuals/wiki/Support-Runbook#deal-with-email-or-sms-still-in-created --- app/celery/nightly_tasks.py | 9 +-------- app/dao/notifications_dao.py | 8 +------- tests/app/celery/test_nightly_tasks.py | 7 ++----- .../dao/notification_dao/test_notification_dao.py | 14 +++++++------- 4 files changed, 11 insertions(+), 27 deletions(-) diff --git a/app/celery/nightly_tasks.py b/app/celery/nightly_tasks.py index 65b9a94d8..410116afc 100644 --- a/app/celery/nightly_tasks.py +++ b/app/celery/nightly_tasks.py @@ -30,7 +30,6 @@ from app.dao.notifications_dao import ( from app.dao.service_callback_api_dao import ( get_service_delivery_status_callback_api_for_service, ) -from app.exceptions import NotificationTechnicalFailureException from app.models import ( EMAIL_TYPE, KEY_TYPE_NORMAL, @@ -123,10 +122,9 @@ def timeout_notifications(): # dao_timeout_notifications to return up to 100K notifications, so this task # will operate on up to 500K - normally we only get around 20K. for _ in range(0, 5): - technical_failure_notifications, temporary_failure_notifications = \ + notifications = \ dao_timeout_notifications(current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD')) - notifications = technical_failure_notifications + temporary_failure_notifications for notification in notifications: # queue callback task only if the service_callback_api exists service_callback_api = get_service_delivery_status_callback_api_for_service(service_id=notification.service_id) # noqa: E501 @@ -137,11 +135,6 @@ def timeout_notifications(): current_app.logger.info( "Timeout period reached for {} notifications, status has been updated.".format(len(notifications))) - if technical_failure_notifications: - message = "{} notifications have been updated to technical-failure because they " \ - "have timed out and are still in created.Notification ids: {}".format( - len(technical_failure_notifications), [str(x.id) for x in technical_failure_notifications]) - raise NotificationTechnicalFailureException(message) if len(notifications) < 100000: return diff --git a/app/dao/notifications_dao.py b/app/dao/notifications_dao.py index 1a823c5dd..f5700ea68 100644 --- a/app/dao/notifications_dao.py +++ b/app/dao/notifications_dao.py @@ -526,9 +526,6 @@ def dao_timeout_notifications(timeout_period_in_seconds): """ Timeout SMS and email notifications by the following rules: - we never sent the notification to the provider for some reason - created -> technical-failure - the notification was sent to the provider but there was not a delivery receipt sending -> temporary-failure pending -> temporary-failure @@ -539,16 +536,13 @@ def dao_timeout_notifications(timeout_period_in_seconds): updated_at = datetime.utcnow() timeout = functools.partial(_timeout_notifications, timeout_start=timeout_start, updated_at=updated_at) - # Notifications still in created status are marked with a technical-failure: - technical_failure_notifications = timeout([NOTIFICATION_CREATED], NOTIFICATION_TECHNICAL_FAILURE) - # Notifications still in sending or pending status are marked with a temporary-failure: temporary_failure_notifications = timeout([NOTIFICATION_SENDING, NOTIFICATION_PENDING], NOTIFICATION_TEMPORARY_FAILURE) db.session.commit() - return technical_failure_notifications, temporary_failure_notifications + return temporary_failure_notifications def is_delivery_slow_for_providers( diff --git a/tests/app/celery/test_nightly_tasks.py b/tests/app/celery/test_nightly_tasks.py index 8813b92fd..32f7e1e80 100644 --- a/tests/app/celery/test_nightly_tasks.py +++ b/tests/app/celery/test_nightly_tasks.py @@ -28,7 +28,6 @@ from app.celery.service_callback_tasks import ( create_delivery_status_callback_data, ) from app.config import QueueNames -from app.exceptions import NotificationTechnicalFailureException from app.models import EMAIL_TYPE, LETTER_TYPE, SMS_TYPE, FactProcessingTime from tests.app.db import ( create_job, @@ -184,11 +183,9 @@ def test_update_status_of_notifications_after_timeout(notify_api, sample_templat status='pending', created_at=datetime.utcnow() - timedelta( seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) - with pytest.raises(NotificationTechnicalFailureException) as e: - timeout_notifications() - assert str(not2.id) in str(e.value) + timeout_notifications() assert not1.status == 'temporary-failure' - assert not2.status == 'technical-failure' + assert not2.status == 'created' assert not3.status == 'temporary-failure' diff --git a/tests/app/dao/notification_dao/test_notification_dao.py b/tests/app/dao/notification_dao/test_notification_dao.py index 25e4ca261..180d0ec92 100644 --- a/tests/app/dao/notification_dao/test_notification_dao.py +++ b/tests/app/dao/notification_dao/test_notification_dao.py @@ -703,12 +703,12 @@ def test_dao_timeout_notifications(sample_template): assert Notification.query.get(sending.id).status == 'sending' assert Notification.query.get(pending.id).status == 'pending' assert Notification.query.get(delivered.id).status == 'delivered' - technical_failure_notifications, temporary_failure_notifications = dao_timeout_notifications(1) - assert Notification.query.get(created.id).status == 'technical-failure' + temporary_failure_notifications = dao_timeout_notifications(1) + assert Notification.query.get(created.id).status == 'created' assert Notification.query.get(sending.id).status == 'temporary-failure' assert Notification.query.get(pending.id).status == 'temporary-failure' assert Notification.query.get(delivered.id).status == 'delivered' - assert len(technical_failure_notifications + temporary_failure_notifications) == 3 + assert len(temporary_failure_notifications) == 2 def test_dao_timeout_notifications_only_updates_for_older_notifications(sample_template): @@ -722,8 +722,8 @@ def test_dao_timeout_notifications_only_updates_for_older_notifications(sample_t assert Notification.query.get(sending.id).status == 'sending' assert Notification.query.get(pending.id).status == 'pending' assert Notification.query.get(delivered.id).status == 'delivered' - technical_failure_notifications, temporary_failure_notifications = dao_timeout_notifications(1) - assert len(technical_failure_notifications + temporary_failure_notifications) == 0 + temporary_failure_notifications = dao_timeout_notifications(1) + assert len(temporary_failure_notifications) == 0 def test_dao_timeout_notifications_doesnt_affect_letters(sample_letter_template): @@ -737,8 +737,8 @@ def test_dao_timeout_notifications_doesnt_affect_letters(sample_letter_template) assert Notification.query.get(sending.id).status == 'sending' assert Notification.query.get(pending.id).status == 'pending' assert Notification.query.get(delivered.id).status == 'delivered' - - technical_failure_notifications, temporary_failure_notifications = dao_timeout_notifications(1) + temporary_failure_notifications = dao_timeout_notifications(1) + assert len(temporary_failure_notifications) == 0 def test_should_return_notifications_excluding_jobs_by_default(sample_template, sample_job, sample_api_key): From 97b58ed4c3ef880afde861c892ad9e6025bde65c Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 17:52:16 +0000 Subject: [PATCH 04/13] Remove unnecessary _timeout partial function It's no longer necessary to have a separate function that's now only called once. While sometimes the separation can bring clarity, here I think it's clearer to have all the code in one place, and avoid the functools complexity we had before. --- app/dao/notifications_dao.py | 53 +++++++++++++++--------------------- 1 file changed, 22 insertions(+), 31 deletions(-) diff --git a/app/dao/notifications_dao.py b/app/dao/notifications_dao.py index f5700ea68..48a45b597 100644 --- a/app/dao/notifications_dao.py +++ b/app/dao/notifications_dao.py @@ -1,4 +1,3 @@ -import functools from datetime import datetime, timedelta from itertools import groupby from operator import attrgetter @@ -40,7 +39,6 @@ from app.models import ( NOTIFICATION_SENDING, NOTIFICATION_SENT, NOTIFICATION_STATUS_TYPES_COMPLETED, - NOTIFICATION_TECHNICAL_FAILURE, NOTIFICATION_TEMPORARY_FAILURE, SMS_TYPE, FactNotificationStatus, @@ -489,29 +487,6 @@ def dao_delete_notifications_by_id(notification_id): ).delete(synchronize_session='fetch') -def _timeout_notifications(current_statuses, new_status, timeout_start, updated_at): - # TEMPORARY: limit the notifications to 100K as otherwise we - # see an issues where the task vanishes after it starts executing - # - we believe this is a OOM error but there are no logs. From - # experimentation we've found we can safely process up to 100K. - notifications = Notification.query.filter( - Notification.created_at < timeout_start, - Notification.status.in_(current_statuses), - Notification.notification_type.in_([SMS_TYPE, EMAIL_TYPE]) - ).limit(100000).all() - - Notification.query.filter( - Notification.created_at < timeout_start, - Notification.status.in_(current_statuses), - Notification.notification_type.in_([SMS_TYPE, EMAIL_TYPE]), - Notification.id.in_([n.id for n in notifications]), - ).update( - {'status': new_status, 'updated_at': updated_at}, - synchronize_session=False - ) - return notifications - - def dao_check_notifications_still_in_created(minimum_age_in_seconds): min_created_at = datetime.utcnow() - timedelta(seconds=minimum_age_in_seconds) @@ -534,15 +509,31 @@ def dao_timeout_notifications(timeout_period_in_seconds): """ timeout_start = datetime.utcnow() - timedelta(seconds=timeout_period_in_seconds) updated_at = datetime.utcnow() - timeout = functools.partial(_timeout_notifications, timeout_start=timeout_start, updated_at=updated_at) + current_statuses = [NOTIFICATION_SENDING, NOTIFICATION_PENDING] + new_status = NOTIFICATION_TEMPORARY_FAILURE - # Notifications still in sending or pending status are marked with a temporary-failure: - temporary_failure_notifications = timeout([NOTIFICATION_SENDING, NOTIFICATION_PENDING], - NOTIFICATION_TEMPORARY_FAILURE) + # TEMPORARY: limit the notifications to 100K as otherwise we + # see an issues where the task vanishes after it starts executing + # - we believe this is a OOM error but there are no logs. From + # experimentation we've found we can safely process up to 100K. + notifications = Notification.query.filter( + Notification.created_at < timeout_start, + Notification.status.in_(current_statuses), + Notification.notification_type.in_([SMS_TYPE, EMAIL_TYPE]) + ).limit(100000).all() + + Notification.query.filter( + Notification.created_at < timeout_start, + Notification.status.in_(current_statuses), + Notification.notification_type.in_([SMS_TYPE, EMAIL_TYPE]), + Notification.id.in_([n.id for n in notifications]), + ).update( + {'status': new_status, 'updated_at': updated_at}, + synchronize_session=False + ) db.session.commit() - - return temporary_failure_notifications + return notifications def is_delivery_slow_for_providers( From 05bd26d444d62a55a095865675a163be7ea1f41c Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 17:57:11 +0000 Subject: [PATCH 05/13] Fix names for a few tests in test_nightly_tasks.py I find it really difficult to visually parse test files unless we have a consistent convention for how we name our test functions. In most of our tests the name of the test function starts with the name of the function under test. --- tests/app/celery/test_nightly_tasks.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/tests/app/celery/test_nightly_tasks.py b/tests/app/celery/test_nightly_tasks.py index 32f7e1e80..6d843ff12 100644 --- a/tests/app/celery/test_nightly_tasks.py +++ b/tests/app/celery/test_nightly_tasks.py @@ -147,26 +147,26 @@ def test_remove_csv_files_filters_by_type(mocker, sample_service): ] -def test_should_call_delete_sms_notifications_more_than_week_in_task(notify_api, mocker): +def test_delete_sms_notifications_older_than_retention_calls_child_task(notify_api, mocker): mocked = mocker.patch('app.celery.nightly_tasks.delete_notifications_older_than_retention_by_type') delete_sms_notifications_older_than_retention() mocked.assert_called_once_with('sms') -def test_should_call_delete_email_notifications_more_than_week_in_task(notify_api, mocker): +def test_delete_email_notifications_older_than_retentions_calls_child_task(notify_api, mocker): mocked_notifications = mocker.patch( 'app.celery.nightly_tasks.delete_notifications_older_than_retention_by_type') delete_email_notifications_older_than_retention() mocked_notifications.assert_called_once_with('email') -def test_should_call_delete_letter_notifications_more_than_week_in_task(notify_api, mocker): +def test_delete_letter_notifications_older_than_retention_calls_child_task(notify_api, mocker): mocked = mocker.patch('app.celery.nightly_tasks.delete_notifications_older_than_retention_by_type') delete_letter_notifications_older_than_retention() mocked.assert_called_once_with('letter') -def test_update_status_of_notifications_after_timeout(notify_api, sample_template): +def test_timeout_notifications_after_timeout(notify_api, sample_template): with notify_api.test_request_context(): not1 = create_notification( template=sample_template, @@ -189,7 +189,7 @@ def test_update_status_of_notifications_after_timeout(notify_api, sample_templat assert not3.status == 'temporary-failure' -def test_not_update_status_of_notification_before_timeout(notify_api, sample_template): +def test_timeout_notifications_before_timeout(notify_api, sample_template): with notify_api.test_request_context(): not1 = create_notification( template=sample_template, @@ -200,7 +200,7 @@ def test_not_update_status_of_notification_before_timeout(notify_api, sample_tem assert not1.status == 'sending' -def test_should_not_update_status_of_letter_notifications(client, sample_letter_template): +def test_timeout_notifications_avoids_letters(client, sample_letter_template): created_at = datetime.utcnow() - timedelta(days=5) not1 = create_notification(template=sample_letter_template, status='sending', created_at=created_at) not2 = create_notification(template=sample_letter_template, status='created', created_at=created_at) @@ -225,7 +225,7 @@ def test_timeout_notifications_sends_status_update_to_service(client, sample_tem mocked.assert_called_once_with([str(notification.id), encrypted_data], queue=QueueNames.CALLBACKS) -def test_should_call_delete_inbound_sms(notify_api, mocker): +def test_delete_inbound_sms_calls_child_task(notify_api, mocker): mocker.patch('app.celery.nightly_tasks.delete_inbound_sms_older_than_retention') delete_inbound_sms() assert nightly_tasks.delete_inbound_sms_older_than_retention.call_count == 1 From c3e11d676f604faf4693a1fbad742b7fa0af5b45 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 17:59:37 +0000 Subject: [PATCH 06/13] Remove unnecessary test_request_context manager This doesn't affect how the tests run and just adds complexity. --- tests/app/celery/test_nightly_tasks.py | 54 +++++++++++++------------- 1 file changed, 26 insertions(+), 28 deletions(-) diff --git a/tests/app/celery/test_nightly_tasks.py b/tests/app/celery/test_nightly_tasks.py index 6d843ff12..f1be7defe 100644 --- a/tests/app/celery/test_nightly_tasks.py +++ b/tests/app/celery/test_nightly_tasks.py @@ -167,37 +167,35 @@ def test_delete_letter_notifications_older_than_retention_calls_child_task(notif def test_timeout_notifications_after_timeout(notify_api, sample_template): - with notify_api.test_request_context(): - not1 = create_notification( - template=sample_template, - status='sending', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) - not2 = create_notification( - template=sample_template, - status='created', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) - not3 = create_notification( - template=sample_template, - status='pending', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) - timeout_notifications() - assert not1.status == 'temporary-failure' - assert not2.status == 'created' - assert not3.status == 'temporary-failure' + not1 = create_notification( + template=sample_template, + status='sending', + created_at=datetime.utcnow() - timedelta( + seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) + not2 = create_notification( + template=sample_template, + status='created', + created_at=datetime.utcnow() - timedelta( + seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) + not3 = create_notification( + template=sample_template, + status='pending', + created_at=datetime.utcnow() - timedelta( + seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) + timeout_notifications() + assert not1.status == 'temporary-failure' + assert not2.status == 'created' + assert not3.status == 'temporary-failure' def test_timeout_notifications_before_timeout(notify_api, sample_template): - with notify_api.test_request_context(): - not1 = create_notification( - template=sample_template, - status='sending', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') - 10)) - timeout_notifications() - assert not1.status == 'sending' + not1 = create_notification( + template=sample_template, + status='sending', + created_at=datetime.utcnow() - timedelta( + seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') - 10)) + timeout_notifications() + assert not1.status == 'sending' def test_timeout_notifications_avoids_letters(client, sample_letter_template): From 8b7e81958d3058fb57e4ff2dd77f7244778d662b Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 18:03:54 +0000 Subject: [PATCH 07/13] Delete duplicate 'timeout' tests for notifications These scenarios are already covered by the DAO tests. It's enough to just check the DAO function is called as expected. While sometimes it can be better to have more end-to-end tests, the convention across much of this app is to do unit tests. --- tests/app/celery/test_nightly_tasks.py | 44 ++++---------------------- 1 file changed, 6 insertions(+), 38 deletions(-) diff --git a/tests/app/celery/test_nightly_tasks.py b/tests/app/celery/test_nightly_tasks.py index f1be7defe..e59f8721b 100644 --- a/tests/app/celery/test_nightly_tasks.py +++ b/tests/app/celery/test_nightly_tasks.py @@ -166,47 +166,15 @@ def test_delete_letter_notifications_older_than_retention_calls_child_task(notif mocked.assert_called_once_with('letter') -def test_timeout_notifications_after_timeout(notify_api, sample_template): - not1 = create_notification( - template=sample_template, - status='sending', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) - not2 = create_notification( - template=sample_template, - status='created', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) - not3 = create_notification( - template=sample_template, - status='pending', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) - timeout_notifications() - assert not1.status == 'temporary-failure' - assert not2.status == 'created' - assert not3.status == 'temporary-failure' - - -def test_timeout_notifications_before_timeout(notify_api, sample_template): - not1 = create_notification( - template=sample_template, - status='sending', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') - 10)) - timeout_notifications() - assert not1.status == 'sending' - - -def test_timeout_notifications_avoids_letters(client, sample_letter_template): - created_at = datetime.utcnow() - timedelta(days=5) - not1 = create_notification(template=sample_letter_template, status='sending', created_at=created_at) - not2 = create_notification(template=sample_letter_template, status='created', created_at=created_at) +def test_timeout_notifications(mocker, notify_api, sample_notification): + mock_dao = mocker.patch('app.celery.nightly_tasks.dao_timeout_notifications') + mock_dao.return_value = [sample_notification] timeout_notifications() - assert not1.status == 'sending' - assert not2.status == 'created' + mock_dao.assert_called_once_with( + current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + ) def test_timeout_notifications_sends_status_update_to_service(client, sample_template, mocker): From 5bf3fe6c0fd8d7c195f7177e702706e964d6cd78 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 18:13:21 +0000 Subject: [PATCH 08/13] Clarify no callbacks are sent in timeout test This now complements the test below it, which we will refactor to be consistent in the next commit. --- tests/app/celery/test_nightly_tasks.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/app/celery/test_nightly_tasks.py b/tests/app/celery/test_nightly_tasks.py index e59f8721b..5a4119040 100644 --- a/tests/app/celery/test_nightly_tasks.py +++ b/tests/app/celery/test_nightly_tasks.py @@ -166,7 +166,8 @@ def test_delete_letter_notifications_older_than_retention_calls_child_task(notif mocked.assert_called_once_with('letter') -def test_timeout_notifications(mocker, notify_api, sample_notification): +def test_timeout_notifications_no_callbacks(mocker, sample_notification): + mock_update = mocker.patch('app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async') mock_dao = mocker.patch('app.celery.nightly_tasks.dao_timeout_notifications') mock_dao.return_value = [sample_notification] @@ -176,6 +177,7 @@ def test_timeout_notifications(mocker, notify_api, sample_notification): current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') ) + mock_update.assert_not_called() def test_timeout_notifications_sends_status_update_to_service(client, sample_template, mocker): callback_api = create_service_callback_api(service=sample_template.service) From aea555fce2af617c3350407f49a701a13607f4cd Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 25 Nov 2021 18:14:02 +0000 Subject: [PATCH 09/13] Make test for timeout with callbacks consistent This now matches the behaviour of the test above it: mocking out the DAO function in order to focus on the specific behaviour of the function under test. --- tests/app/celery/test_nightly_tasks.py | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/tests/app/celery/test_nightly_tasks.py b/tests/app/celery/test_nightly_tasks.py index 5a4119040..6bcb3a139 100644 --- a/tests/app/celery/test_nightly_tasks.py +++ b/tests/app/celery/test_nightly_tasks.py @@ -179,18 +179,17 @@ def test_timeout_notifications_no_callbacks(mocker, sample_notification): mock_update.assert_not_called() -def test_timeout_notifications_sends_status_update_to_service(client, sample_template, mocker): - callback_api = create_service_callback_api(service=sample_template.service) - mocked = mocker.patch('app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async') - notification = create_notification( - template=sample_template, - status='sending', - created_at=datetime.utcnow() - timedelta( - seconds=current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') + 10)) + +def test_timeout_notifications_with_callbacks(mocker, sample_notification): + mock_update = mocker.patch('app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async') + mock_dao = mocker.patch('app.celery.nightly_tasks.dao_timeout_notifications') + mock_dao.return_value = [sample_notification] + + callback_api = create_service_callback_api(service=sample_notification.service) timeout_notifications() - encrypted_data = create_delivery_status_callback_data(notification, callback_api) - mocked.assert_called_once_with([str(notification.id), encrypted_data], queue=QueueNames.CALLBACKS) + encrypted_data = create_delivery_status_callback_data(sample_notification, callback_api) + mock_update.assert_called_once_with([str(sample_notification.id), encrypted_data], queue=QueueNames.CALLBACKS) def test_delete_inbound_sms_calls_child_task(notify_api, mocker): From 04da017558e7aaf2c47c3e46e9a7b8c8005b4477 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Fri, 26 Nov 2021 15:18:53 +0000 Subject: [PATCH 10/13] DRY-up conditionally creating callback tasks This removes 3 duplicate instances of the same code, which is still tested implicitly via test_process_ses_receipt_tasks [1]. In the next commit we'll make this test more explicit, to reflect that it's now being reused elsewhere and shouldn't change arbitrarily. We do lose the "print" statement from the command instance of the code, but I think that's a very tolerable loss. [1]: https://github.com/alphagov/notifications-api/blob/16ec8ccb8a6e4284eef7ec27c389419b761f39f0/tests/app/celery/test_process_ses_receipts_tasks.py#L94 --- app/celery/nightly_tasks.py | 17 +++-------- app/celery/process_ses_receipts_tasks.py | 4 +-- .../process_sms_client_response_tasks.py | 18 +++--------- app/commands.py | 28 +++---------------- .../notifications_ses_callback.py | 2 +- tests/app/celery/test_nightly_tasks.py | 23 ++------------- .../test_process_client_response.py | 26 +++-------------- tests/app/test_commands.py | 24 ++-------------- 8 files changed, 25 insertions(+), 117 deletions(-) diff --git a/app/celery/nightly_tasks.py b/app/celery/nightly_tasks.py index 410116afc..92d401f46 100644 --- a/app/celery/nightly_tasks.py +++ b/app/celery/nightly_tasks.py @@ -10,10 +10,6 @@ from sqlalchemy.exc import SQLAlchemyError from app import notify_celery, zendesk_client from app.aws import s3 -from app.celery.service_callback_tasks import ( - create_delivery_status_callback_data, - send_delivery_status_to_service, -) from app.config import QueueNames from app.cronitor import cronitor from app.dao.fact_processing_time_dao import insert_update_processing_time @@ -27,9 +23,6 @@ from app.dao.notifications_dao import ( dao_timeout_notifications, delete_notifications_older_than_retention_by_type, ) -from app.dao.service_callback_api_dao import ( - get_service_delivery_status_callback_api_for_service, -) from app.models import ( EMAIL_TYPE, KEY_TYPE_NORMAL, @@ -39,6 +32,9 @@ from app.models import ( FactProcessingTime, Notification, ) +from app.notifications.notifications_ses_callback import ( + check_and_queue_callback_task, +) from app.utils import get_london_midnight_in_utc @@ -126,12 +122,7 @@ def timeout_notifications(): dao_timeout_notifications(current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD')) for notification in notifications: - # queue callback task only if the service_callback_api exists - service_callback_api = get_service_delivery_status_callback_api_for_service(service_id=notification.service_id) # noqa: E501 - if service_callback_api: - encrypted_notification = create_delivery_status_callback_data(notification, service_callback_api) - send_delivery_status_to_service.apply_async([str(notification.id), encrypted_notification], - queue=QueueNames.CALLBACKS) + check_and_queue_callback_task(notification) current_app.logger.info( "Timeout period reached for {} notifications, status has been updated.".format(len(notifications))) diff --git a/app/celery/process_ses_receipts_tasks.py b/app/celery/process_ses_receipts_tasks.py index fef0fb1f7..04a8d14f1 100644 --- a/app/celery/process_ses_receipts_tasks.py +++ b/app/celery/process_ses_receipts_tasks.py @@ -11,8 +11,8 @@ from app.config import QueueNames from app.dao import notifications_dao from app.models import NOTIFICATION_PENDING, NOTIFICATION_SENDING from app.notifications.notifications_ses_callback import ( - _check_and_queue_callback_task, _check_and_queue_complaint_callback_task, + check_and_queue_callback_task, determine_notification_bounce_type, handle_complaint, ) @@ -76,7 +76,7 @@ def process_ses_results(self, response): notification.sent_at ) - _check_and_queue_callback_task(notification) + check_and_queue_callback_task(notification) return True diff --git a/app/celery/process_sms_client_response_tasks.py b/app/celery/process_sms_client_response_tasks.py index 6cc04d7fb..e16175646 100644 --- a/app/celery/process_sms_client_response_tasks.py +++ b/app/celery/process_sms_client_response_tasks.py @@ -5,20 +5,15 @@ from flask import current_app from notifications_utils.template import SMSMessageTemplate from app import notify_celery, statsd_client -from app.celery.service_callback_tasks import ( - create_delivery_status_callback_data, - send_delivery_status_to_service, -) from app.clients import ClientException from app.clients.sms.firetext import get_firetext_responses from app.clients.sms.mmg import get_mmg_responses -from app.config import QueueNames from app.dao import notifications_dao -from app.dao.service_callback_api_dao import ( - get_service_delivery_status_callback_api_for_service, -) from app.dao.templates_dao import dao_get_template_by_id from app.models import NOTIFICATION_PENDING +from app.notifications.notifications_ses_callback import ( + check_and_queue_callback_task, +) sms_response_mapper = { 'MMG': get_mmg_responses, @@ -94,9 +89,4 @@ def _process_for_status(notification_status, client_name, provider_reference, de notifications_dao.dao_update_notification(notification) if notification_status != NOTIFICATION_PENDING: - service_callback_api = get_service_delivery_status_callback_api_for_service(service_id=notification.service_id) - # queue callback task only if the service_callback_api exists - if service_callback_api: - encrypted_notification = create_delivery_status_callback_data(notification, service_callback_api) - send_delivery_status_to_service.apply_async([str(notification.id), encrypted_notification], - queue=QueueNames.CALLBACKS) + check_and_queue_callback_task(notification) diff --git a/app/commands.py b/app/commands.py index 2cf43f8f6..1b8230922 100644 --- a/app/commands.py +++ b/app/commands.py @@ -26,10 +26,6 @@ from app.celery.letters_pdf_tasks import ( from app.celery.reporting_tasks import ( create_nightly_notification_status_for_day, ) -from app.celery.service_callback_tasks import ( - create_delivery_status_callback_data, - send_delivery_status_to_service, -) from app.celery.tasks import process_row, record_daily_sorted_counts from app.config import QueueNames from app.dao.annual_billing_dao import ( @@ -52,9 +48,6 @@ from app.dao.permissions_dao import permission_dao from app.dao.provider_rates_dao import ( create_provider_rates as dao_create_provider_rates, ) -from app.dao.service_callback_api_dao import ( - get_service_delivery_status_callback_api_for_service, -) from app.dao.services_dao import ( dao_fetch_all_services_by_user, dao_fetch_all_services_created_by_user, @@ -85,6 +78,9 @@ from app.models import ( Service, User, ) +from app.notifications.notifications_ses_callback import ( + check_and_queue_callback_task, +) from app.utils import get_london_midnight_in_utc @@ -295,23 +291,7 @@ def replay_callbacks(file_name): for id in [id.strip() for id in file]: try: notification = Notification.query.filter_by(id=id).one() - - callback_api = get_service_delivery_status_callback_api_for_service( - service_id=notification.service_id - ) - - if not callback_api: - print(f"Callback api was not found for notification: {id}.") - continue - - encrypted_status_update = create_delivery_status_callback_data( - notification, callback_api - ) - - send_delivery_status_to_service.apply_async( - [id, encrypted_status_update], queue=QueueNames.CALLBACKS - ) - + check_and_queue_callback_task(notification) print(f"Created callback task for notification: {id}.") except NoResultFound: print(f"ID: {id} was not found in notifications.") diff --git a/app/notifications/notifications_ses_callback.py b/app/notifications/notifications_ses_callback.py index 484d78f30..c1fdceaa0 100644 --- a/app/notifications/notifications_ses_callback.py +++ b/app/notifications/notifications_ses_callback.py @@ -68,7 +68,7 @@ def remove_emails_from_complaint(complaint_dict): return complaint_dict['mail'].pop('destination') -def _check_and_queue_callback_task(notification): +def check_and_queue_callback_task(notification): # queue callback task only if the service_callback_api exists service_callback_api = get_service_delivery_status_callback_api_for_service(service_id=notification.service_id) if service_callback_api: diff --git a/tests/app/celery/test_nightly_tasks.py b/tests/app/celery/test_nightly_tasks.py index 6bcb3a139..7a6167aa2 100644 --- a/tests/app/celery/test_nightly_tasks.py +++ b/tests/app/celery/test_nightly_tasks.py @@ -24,16 +24,11 @@ from app.celery.nightly_tasks import ( save_daily_notification_processing_time, timeout_notifications, ) -from app.celery.service_callback_tasks import ( - create_delivery_status_callback_data, -) -from app.config import QueueNames from app.models import EMAIL_TYPE, LETTER_TYPE, SMS_TYPE, FactProcessingTime from tests.app.db import ( create_job, create_notification, create_service, - create_service_callback_api, create_service_data_retention, create_template, ) @@ -166,8 +161,8 @@ def test_delete_letter_notifications_older_than_retention_calls_child_task(notif mocked.assert_called_once_with('letter') -def test_timeout_notifications_no_callbacks(mocker, sample_notification): - mock_update = mocker.patch('app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async') +def test_timeout_notifications(mocker, sample_notification): + mock_update = mocker.patch('app.celery.nightly_tasks.check_and_queue_callback_task') mock_dao = mocker.patch('app.celery.nightly_tasks.dao_timeout_notifications') mock_dao.return_value = [sample_notification] @@ -177,19 +172,7 @@ def test_timeout_notifications_no_callbacks(mocker, sample_notification): current_app.config.get('SENDING_NOTIFICATIONS_TIMEOUT_PERIOD') ) - mock_update.assert_not_called() - - -def test_timeout_notifications_with_callbacks(mocker, sample_notification): - mock_update = mocker.patch('app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async') - mock_dao = mocker.patch('app.celery.nightly_tasks.dao_timeout_notifications') - mock_dao.return_value = [sample_notification] - - callback_api = create_service_callback_api(service=sample_notification.service) - timeout_notifications() - - encrypted_data = create_delivery_status_callback_data(sample_notification, callback_api) - mock_update.assert_called_once_with([str(sample_notification.id), encrypted_data], queue=QueueNames.CALLBACKS) + mock_update.assert_called_once_with(sample_notification) def test_delete_inbound_sms_calls_child_task(notify_api, mocker): diff --git a/tests/app/notifications/test_process_client_response.py b/tests/app/notifications/test_process_client_response.py index f31a9c9ed..6005fbce3 100644 --- a/tests/app/notifications/test_process_client_response.py +++ b/tests/app/notifications/test_process_client_response.py @@ -8,12 +8,8 @@ from app import statsd_client from app.celery.process_sms_client_response_tasks import ( process_sms_client_response, ) -from app.celery.service_callback_tasks import ( - create_delivery_status_callback_data, -) from app.clients import ClientException from app.models import NOTIFICATION_TECHNICAL_FAILURE -from tests.app.db import create_service_callback_api def test_process_sms_client_response_raises_error_if_reference_is_not_a_valid_uuid(client): @@ -121,12 +117,7 @@ def test_process_sms_client_response_updates_notification_status_when_detailed_s def test_sms_response_does_not_send_callback_if_notification_is_not_in_the_db(sample_service, mocker): - mocker.patch( - 'app.celery.process_sms_client_response_tasks.get_service_delivery_status_callback_api_for_service', - return_value='mock-delivery-callback-for-service') - send_mock = mocker.patch( - 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' - ) + send_mock = mocker.patch('app.celery.process_sms_client_response_tasks.check_and_queue_callback_task') reference = str(uuid.uuid4()) process_sms_client_response(status='3', provider_reference=reference, client_name='MMG') send_mock.assert_not_called() @@ -156,26 +147,17 @@ def test_process_sms_updates_billable_units_if_zero(sample_notification): def test_process_sms_response_does_not_send_service_callback_for_pending_notifications(sample_notification, mocker): - mocker.patch( - 'app.celery.process_sms_client_response_tasks.get_service_delivery_status_callback_api_for_service', - return_value='fake-callback') - send_mock = mocker.patch('app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async') + send_mock = mocker.patch('app.celery.process_sms_client_response_tasks.check_and_queue_callback_task') process_sms_client_response('2', str(sample_notification.id), 'Firetext') send_mock.assert_not_called() def test_outcome_statistics_called_for_successful_callback(sample_notification, mocker): - send_mock = mocker.patch( - 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' - ) - callback_api = create_service_callback_api(service=sample_notification.service, url="https://original_url.com") + send_mock = mocker.patch('app.celery.process_sms_client_response_tasks.check_and_queue_callback_task') reference = str(sample_notification.id) process_sms_client_response('3', reference, 'MMG') - - encrypted_data = create_delivery_status_callback_data(sample_notification, callback_api) - send_mock.assert_called_once_with([reference, encrypted_data], - queue="service-callbacks") + send_mock.assert_called_once_with(sample_notification) def test_process_sms_updates_sent_by_with_client_name_if_not_in_noti(sample_notification): diff --git a/tests/app/test_commands.py b/tests/app/test_commands.py index 98f092a89..aef033ca5 100644 --- a/tests/app/test_commands.py +++ b/tests/app/test_commands.py @@ -1,9 +1,8 @@ import uuid from app.commands import local_dev_broadcast_permissions, replay_callbacks -from app.config import QueueNames from app.dao.services_dao import dao_add_user_to_service -from tests.app.db import create_service_callback_api, create_user +from tests.app.db import create_user def test_local_dev_broadcast_permissions( @@ -33,10 +32,7 @@ def test_replay_callbacks( tmpdir, notify_api, ): - mock_apply = mocker.patch('app.commands.send_delivery_status_to_service.apply_async') - mock_update = mocker.patch('app.commands.create_delivery_status_callback_data') - mock_update.return_value = 'encrypted_status_update' - + mock_task = mocker.patch('app.commands.check_and_queue_callback_task') file_path = tmpdir + 'callback_ids.txt' missing_notification_id = uuid.uuid4() @@ -48,20 +44,6 @@ def test_replay_callbacks( replay_callbacks, ['-f', file_path] ) - mock_apply.assert_not_called() assert f'{missing_notification_id} was not found' in result.output - assert "Callback api was not found" in result.output - - # Now re-run with the callback API in place - create_service_callback_api(service=sample_service, bearer_token='foo') - - result = notify_api.test_cli_runner().invoke( - replay_callbacks, ['-f', file_path] - ) - - mock_apply.assert_called_once_with( - [str(sample_notification.id), 'encrypted_status_update'], - queue=QueueNames.CALLBACKS - ) - + mock_task.assert_called_once_with(sample_notification) assert result.exit_code == 0 From 9bd2a9b427c9c2c2416f08cba35ed188c1159426 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Fri, 26 Nov 2021 15:57:31 +0000 Subject: [PATCH 11/13] Extract tests for conditionally creating callback This will help ensure the function doesn't change arbitrarily, now that it's used in multiple other places. --- .../celery/test_process_ses_receipts_tasks.py | 43 +++---------------- .../test_notifications_ses_callback.py | 40 ++++++++++++++++- 2 files changed, 44 insertions(+), 39 deletions(-) diff --git a/tests/app/celery/test_process_ses_receipts_tasks.py b/tests/app/celery/test_process_ses_receipts_tasks.py index ee8c2081b..290b1029b 100644 --- a/tests/app/celery/test_process_ses_receipts_tasks.py +++ b/tests/app/celery/test_process_ses_receipts_tasks.py @@ -10,9 +10,6 @@ from app.celery.research_mode_tasks import ( ses_notification_callback, ses_soft_bounce_callback, ) -from app.celery.service_callback_tasks import ( - create_delivery_status_callback_data, -) from app.dao.notifications_dao import get_notification_by_id from app.models import Complaint, Notification from app.notifications.notifications_ses_callback import ( @@ -72,15 +69,13 @@ def test_ses_callback_should_update_notification_status( mocker.patch('app.statsd_client.incr') mocker.patch('app.statsd_client.timing_with_dates') send_mock = mocker.patch( - 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' + 'app.celery.process_ses_receipts_tasks.check_and_queue_callback_task' ) notification = create_notification( template=sample_email_template, status='sending', reference='ref', ) - callback_api = create_service_callback_api(service=sample_email_template.service, - url="https://original_url.com") assert get_notification_by_id(notification.id).status == 'sending' assert process_ses_results(ses_notification_callback(reference='ref')) @@ -90,8 +85,7 @@ def test_ses_callback_should_update_notification_status( ) statsd_client.incr.assert_any_call("callback.ses.delivered") updated_notification = Notification.query.get(notification.id) - encrypted_data = create_delivery_status_callback_data(updated_notification, callback_api) - send_mock.assert_called_once_with([str(notification.id), encrypted_data], queue="service-callbacks") + send_mock.assert_called_once_with(updated_notification) def test_ses_callback_should_not_update_notification_status_if_already_delivered(sample_email_template, mocker): @@ -138,30 +132,6 @@ def test_ses_callback_should_not_retry_if_notification_is_old(client, notify_db, assert mock_retry.call_count == 0 -def test_ses_callback_does_not_call_send_delivery_status_if_no_db_entry( - client, - notify_db_session, - sample_email_template, - mocker): - with freeze_time('2001-01-01T12:00:00'): - - send_mock = mocker.patch( - 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' - ) - notification = create_notification( - template=sample_email_template, - status='sending', - reference='ref', - ) - - assert get_notification_by_id(notification.id).status == 'sending' - - assert process_ses_results(ses_notification_callback(reference='ref')) - assert get_notification_by_id(notification.id).status == 'delivered' - - send_mock.assert_not_called() - - def test_ses_callback_should_update_multiple_notification_status_sent( client, notify_db_session, @@ -169,7 +139,7 @@ def test_ses_callback_should_update_multiple_notification_status_sent( mocker): send_mock = mocker.patch( - 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' + 'app.celery.process_ses_receipts_tasks.check_and_queue_callback_task' ) create_notification( template=sample_email_template, @@ -186,7 +156,6 @@ def test_ses_callback_should_update_multiple_notification_status_sent( status='sending', reference='ref3', ) - create_service_callback_api(service=sample_email_template.service, url="https://original_url.com") assert process_ses_results(ses_notification_callback(reference='ref1')) assert process_ses_results(ses_notification_callback(reference='ref2')) assert process_ses_results(ses_notification_callback(reference='ref3')) @@ -198,7 +167,7 @@ def test_ses_callback_should_set_status_to_temporary_failure(client, sample_email_template, mocker): send_mock = mocker.patch( - 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' + 'app.celery.process_ses_receipts_tasks.check_and_queue_callback_task' ) mock_logger = mocker.patch('app.celery.process_ses_receipts_tasks.current_app.logger.info') notification = create_notification( @@ -206,7 +175,6 @@ def test_ses_callback_should_set_status_to_temporary_failure(client, status='sending', reference='ref', ) - create_service_callback_api(service=notification.service, url="https://original_url.com") assert get_notification_by_id(notification.id).status == 'sending' assert process_ses_results(ses_soft_bounce_callback(reference='ref')) assert get_notification_by_id(notification.id).status == 'temporary-failure' @@ -219,7 +187,7 @@ def test_ses_callback_should_set_status_to_permanent_failure(client, sample_email_template, mocker): send_mock = mocker.patch( - 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' + 'app.celery.process_ses_receipts_tasks.check_and_queue_callback_task' ) mock_logger = mocker.patch('app.celery.process_ses_receipts_tasks.current_app.logger.info') notification = create_notification( @@ -227,7 +195,6 @@ def test_ses_callback_should_set_status_to_permanent_failure(client, status='sending', reference='ref', ) - create_service_callback_api(service=sample_email_template.service, url="https://original_url.com") assert get_notification_by_id(notification.id).status == 'sending' assert process_ses_results(ses_hard_bounce_callback(reference='ref')) diff --git a/tests/app/notifications/test_notifications_ses_callback.py b/tests/app/notifications/test_notifications_ses_callback.py index 179aa5564..8e6409eeb 100644 --- a/tests/app/notifications/test_notifications_ses_callback.py +++ b/tests/app/notifications/test_notifications_ses_callback.py @@ -4,10 +4,14 @@ from sqlalchemy.exc import SQLAlchemyError from app.dao.notifications_dao import get_notification_by_id from app.models import Complaint -from app.notifications.notifications_ses_callback import handle_complaint +from app.notifications.notifications_ses_callback import ( + check_and_queue_callback_task, + handle_complaint, +) from tests.app.db import ( create_notification, create_notification_history, + create_service_callback_api, ses_complaint_callback, ses_complaint_callback_malformed_message_id, ses_complaint_callback_with_missing_complaint_type, @@ -64,3 +68,37 @@ def test_process_ses_results_in_complaint_save_complaint_with_null_complaint_typ assert len(complaints) == 1 assert complaints[0].notification_id == notification.id assert not complaints[0].complaint_type + + +def test_check_and_queue_callback_task(mocker, sample_notification): + mock_create = mocker.patch( + 'app.notifications.notifications_ses_callback.create_delivery_status_callback_data' + ) + + mock_send = mocker.patch( + 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' + ) + + callback_api = create_service_callback_api(service=sample_notification.service) + mock_create.return_value = 'encrypted_status_update' + + check_and_queue_callback_task(sample_notification) + + # callback_api doesn't match by equality for some + # reason, so we need to take this approach instead + mock_create_args = mock_create.mock_calls[0][1] + assert mock_create_args[0] == sample_notification + assert mock_create_args[1].id == callback_api.id + + mock_send.assert_called_once_with( + [str(sample_notification.id), mock_create.return_value], queue="service-callbacks" + ) + + +def test_check_and_queue_callback_task_no_callback_api(mocker, sample_notification): + mock_send = mocker.patch( + 'app.celery.service_callback_tasks.send_delivery_status_to_service.apply_async' + ) + + check_and_queue_callback_task(sample_notification) + mock_send.assert_not_called() From ab4cb029dfc7e97d477c960f38baf59277d92990 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Mon, 6 Dec 2021 14:07:52 +0000 Subject: [PATCH 12/13] Remove alert for email / sms in created In response to [1]. [1]: https://github.com/alphagov/notifications-api/pull/3383#discussion_r759379988 It turns out the code that inspired this new alert - in the old "timeout-sending-notifications" task - was actually redundant as we already have a task to "replay" notifications still in "created", which is much better than just alerting about them. It's possible the replayed notifications will also fail, but in both cases we should see some kind of error due to this, so I don't think we're losing anything by not having an alert. --- app/celery/scheduled_tasks.py | 14 ---------- app/config.py | 6 ---- app/dao/notifications_dao.py | 10 ------- tests/app/celery/test_scheduled_tasks.py | 19 ------------- .../notification_dao/test_notification_dao.py | 28 ------------------- 5 files changed, 77 deletions(-) diff --git a/app/celery/scheduled_tasks.py b/app/celery/scheduled_tasks.py index 804194cb5..968a4231d 100644 --- a/app/celery/scheduled_tasks.py +++ b/app/celery/scheduled_tasks.py @@ -30,7 +30,6 @@ from app.dao.jobs_dao import ( find_missing_row_for_job, ) from app.dao.notifications_dao import ( - dao_check_notifications_still_in_created, dao_old_letters_with_created_status, dao_precompiled_letters_still_pending_virus_check, is_delivery_slow_for_providers, @@ -119,19 +118,6 @@ def switch_current_sms_provider_on_slow_delivery(): dao_reduce_sms_provider_priority(provider_name, time_threshold=timedelta(minutes=10)) -@notify_celery.task(name='raise-alert-if-email-sms-still-in-created') -def raise_alert_if_email_sms_still_in_created(): - alert_above_age = current_app.config.get('CREATED_NOTIFICATIONS_ALERT_AGE') - still_in_created = dao_check_notifications_still_in_created(alert_above_age) - message = f"{still_in_created} notifications are still in 'created'." - - if still_in_created == 0: - current_app.logger.info(message) - return - - current_app.logger.error(message) - - @notify_celery.task(name='tend-providers-back-to-middle') def tend_providers_back_to_middle(): dao_adjust_provider_priority_back_to_resting_points() diff --git a/app/config.py b/app/config.py index d953e1433..ab5a08b27 100644 --- a/app/config.py +++ b/app/config.py @@ -310,11 +310,6 @@ class Config(object): 'schedule': crontab(hour=15, minute=30), 'options': {'queue': QueueNames.PERIODIC} }, - 'raise-alert-if-email-sms-still-in-created': { - 'task': 'raise-alert-if-email-sms-still-in-created', - 'schedule': crontab(minute=30), - 'options': {'queue': QueueNames.PERIODIC}, - }, # The collate-letter-pdf does assume it is called in an hour that BST does not make a # difference to the truncate date which translates to the filename to process 'collate-letter-pdfs-to-be-sent': { @@ -360,7 +355,6 @@ class Config(object): STATSD_ENABLED = bool(STATSD_HOST) SENDING_NOTIFICATIONS_TIMEOUT_PERIOD = 259200 # 3 days - CREATED_NOTIFICATIONS_ALERT_AGE = 3600 # 1 hour SIMULATED_EMAIL_ADDRESSES = ( 'simulate-delivered@notifications.service.gov.uk', diff --git a/app/dao/notifications_dao.py b/app/dao/notifications_dao.py index 48a45b597..b8e461705 100644 --- a/app/dao/notifications_dao.py +++ b/app/dao/notifications_dao.py @@ -487,16 +487,6 @@ def dao_delete_notifications_by_id(notification_id): ).delete(synchronize_session='fetch') -def dao_check_notifications_still_in_created(minimum_age_in_seconds): - min_created_at = datetime.utcnow() - timedelta(seconds=minimum_age_in_seconds) - - return Notification.query.filter( - Notification.created_at < min_created_at, - Notification.status == NOTIFICATION_CREATED, - Notification.notification_type.in_([SMS_TYPE, EMAIL_TYPE]) - ).count() - - def dao_timeout_notifications(timeout_period_in_seconds): """ Timeout SMS and email notifications by the following rules: diff --git a/tests/app/celery/test_scheduled_tasks.py b/tests/app/celery/test_scheduled_tasks.py index 68ae6d073..edd8cbeee 100644 --- a/tests/app/celery/test_scheduled_tasks.py +++ b/tests/app/celery/test_scheduled_tasks.py @@ -19,7 +19,6 @@ from app.celery.scheduled_tasks import ( check_job_status, delete_invitations, delete_verify_codes, - raise_alert_if_email_sms_still_in_created, remove_yesterdays_planned_tests_on_govuk_alerts, replay_created_notifications, run_scheduled_jobs, @@ -109,24 +108,6 @@ def test_should_update_all_scheduled_jobs_and_put_on_queue(sample_template, mock ]) -def test_raise_alert_if_email_sms_still_in_created(notify_api, mocker): - mock_check = mocker.patch('app.celery.scheduled_tasks.dao_check_notifications_still_in_created') - mock_logger = mocker.patch('app.celery.scheduled_tasks.current_app.logger') - - mock_check.return_value = 0 - raise_alert_if_email_sms_still_in_created() - mock_logger.info.assert_called_once_with("0 notifications are still in 'created'.") - - assert mock_check.called_once_with( - notify_api.config['CREATED_NOTIFICATIONS_ALERT_AGE'] - ) - - # try again with something to alert about - mock_check.return_value = 1 - raise_alert_if_email_sms_still_in_created() - mock_logger.error.assert_called_once_with("1 notifications are still in 'created'.") - - @freeze_time('2017-05-01 14:00:00') def test_switch_current_sms_provider_on_slow_delivery_switches_when_one_provider_is_slow( mocker, diff --git a/tests/app/dao/notification_dao/test_notification_dao.py b/tests/app/dao/notification_dao/test_notification_dao.py index 180d0ec92..a95bf47d2 100644 --- a/tests/app/dao/notification_dao/test_notification_dao.py +++ b/tests/app/dao/notification_dao/test_notification_dao.py @@ -8,7 +8,6 @@ from sqlalchemy.exc import IntegrityError, SQLAlchemyError from sqlalchemy.orm.exc import NoResultFound from app.dao.notifications_dao import ( - dao_check_notifications_still_in_created, dao_create_notification, dao_delete_notifications_by_id, dao_get_last_notification_added_for_job_id, @@ -665,33 +664,6 @@ def _notification_json(sample_template, job_id=None, id=None, status=None): return data -def test_dao_check_notifications_still_in_created( - sample_template, - sample_email_template, - sample_letter_template -): - with freeze_time(datetime.utcnow() - timedelta(minutes=2)): - # old sending notification (ignored) - create_notification(sample_template, status='sending') - # old letter notification (ignored) - create_notification(sample_letter_template, status='created') - - with freeze_time(datetime.utcnow() + timedelta(minutes=10)): - # new / future notification (ignored) - create_notification(sample_template, status='created') - - # first prove all the above notifications are ignored - assert dao_check_notifications_still_in_created(1) == 0 - - with freeze_time(datetime.utcnow() - timedelta(minutes=2)): - # now add old, eligible notifications - create_notification(sample_template, status='created') - create_notification(sample_email_template, status='created') - - # now prove the check only picks up on these ones - assert dao_check_notifications_still_in_created(1) == 2 - - def test_dao_timeout_notifications(sample_template): with freeze_time(datetime.utcnow() - timedelta(minutes=2)): created = create_notification(sample_template, status='created') From a8edfeb94144d851370f8af8d6419d737e8fb878 Mon Sep 17 00:00:00 2001 From: Ben Thorner Date: Thu, 9 Dec 2021 10:46:19 +0000 Subject: [PATCH 13/13] Remove command to replay callbacks In response to [1]. I've already removed the runbook that referred to this. [1]: https://github.com/alphagov/notifications-api/pull/3383#discussion_r765644576 --- app/commands.py | 20 -------------------- tests/app/test_commands.py | 28 +--------------------------- 2 files changed, 1 insertion(+), 47 deletions(-) diff --git a/app/commands.py b/app/commands.py index 1b8230922..565b83bde 100644 --- a/app/commands.py +++ b/app/commands.py @@ -78,9 +78,6 @@ from app.models import ( Service, User, ) -from app.notifications.notifications_ses_callback import ( - check_and_queue_callback_task, -) from app.utils import get_london_midnight_in_utc @@ -280,23 +277,6 @@ def recreate_pdf_for_precompiled_or_uploaded_letter(notification_id): resanitise_pdf.apply_async([str(notification_id)], queue=QueueNames.LETTERS) -@notify_command(name='replay-callbacks') -@click.option('-f', '--file-name', required=True, - help="""Full path of the file to upload, containing IDs of - notifications that need the status to be sent to the service.""") -def replay_callbacks(file_name): - print("Replaying callbacks.") - file = open(file_name) - - for id in [id.strip() for id in file]: - try: - notification = Notification.query.filter_by(id=id).one() - check_and_queue_callback_task(notification) - print(f"Created callback task for notification: {id}.") - except NoResultFound: - print(f"ID: {id} was not found in notifications.") - - def setup_commands(application): application.cli.add_command(command_group) diff --git a/tests/app/test_commands.py b/tests/app/test_commands.py index aef033ca5..dd8f1c15b 100644 --- a/tests/app/test_commands.py +++ b/tests/app/test_commands.py @@ -1,6 +1,4 @@ -import uuid - -from app.commands import local_dev_broadcast_permissions, replay_callbacks +from app.commands import local_dev_broadcast_permissions from app.dao.services_dao import dao_add_user_to_service from tests.app.db import create_user @@ -23,27 +21,3 @@ def test_local_dev_broadcast_permissions( assert len(user.get_permissions(sample_service.id)) == 0 assert len(user.get_permissions(sample_broadcast_service.id)) > 0 - - -def test_replay_callbacks( - mocker, - sample_service, - sample_notification, - tmpdir, - notify_api, -): - mock_task = mocker.patch('app.commands.check_and_queue_callback_task') - file_path = tmpdir + 'callback_ids.txt' - missing_notification_id = uuid.uuid4() - - with open(file_path, 'w') as f: - f.write(str(sample_notification.id) + "\n") - f.write(str(missing_notification_id) + "\n") - - result = notify_api.test_cli_runner().invoke( - replay_callbacks, ['-f', file_path] - ) - - assert f'{missing_notification_id} was not found' in result.output - mock_task.assert_called_once_with(sample_notification) - assert result.exit_code == 0