From 6f5822ae5b969c3eeb4fce8f9fb6324697311383 Mon Sep 17 00:00:00 2001 From: Alexey Bezhan Date: Wed, 6 Mar 2019 11:35:32 +0000 Subject: [PATCH] Downgrade log level for missing notifications in SES receipt The timestamps available in the SES receipt don't always correspond to the time the notification has been sent. We've seen callbacks with a current timestamp in both 'mail' and 'bounce' objects that referenced a notification sent a week ago, which means we can't rely on it to skip archived notifications. One possible approach would be to look up the notification reference in the notification_history table, but this goes against our plans to stop relying on it in the future. This changes the SES receipts logic to retry missing notifications once (if the callback timestamp is within the last 5 minutes the task will retry after a 5 minute delay) to capture callbacks arriving before the notification reference has been persisted to the DB. Otherwise, we log the missing notification as a warning instead of error. --- app/celery/process_ses_receipts_tasks.py | 6 +++--- tests/app/celery/test_process_ses_receipts_tasks.py | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/app/celery/process_ses_receipts_tasks.py b/app/celery/process_ses_receipts_tasks.py index ebe0cfaf9..3380047f3 100644 --- a/app/celery/process_ses_receipts_tasks.py +++ b/app/celery/process_ses_receipts_tasks.py @@ -42,10 +42,10 @@ def process_ses_results(self, response): notification = notifications_dao.dao_get_notification_by_reference(reference) except NoResultFound: message_time = iso8601.parse_date(ses_message['mail']['timestamp']).replace(tzinfo=None) - if datetime.utcnow() - message_time < timedelta(minutes=10): + if datetime.utcnow() - message_time < timedelta(minutes=5): self.retry(queue=QueueNames.RETRY) - elif datetime.utcnow() - message_time < timedelta(days=3): - current_app.logger.error( + else: + current_app.logger.warning( "notification not found for reference: {} (update to {})".format(reference, notification_status) ) return diff --git a/tests/app/celery/test_process_ses_receipts_tasks.py b/tests/app/celery/test_process_ses_receipts_tasks.py index 3cd27cfd1..0905f1069 100644 --- a/tests/app/celery/test_process_ses_receipts_tasks.py +++ b/tests/app/celery/test_process_ses_receipts_tasks.py @@ -117,7 +117,7 @@ def test_ses_callback_should_retry_if_notification_is_new(client, notify_db, moc def test_ses_callback_should_log_if_notification_is_missing(client, notify_db, mocker): mock_retry = mocker.patch('app.celery.process_ses_receipts_tasks.process_ses_results.retry') - mock_logger = mocker.patch('app.celery.process_ses_receipts_tasks.current_app.logger.error') + mock_logger = mocker.patch('app.celery.process_ses_receipts_tasks.current_app.logger.warning') with freeze_time('2017-11-17T12:34:03.646Z'): assert process_ses_results(ses_notification_callback(reference='ref')) is None