From 2355ee011f36f4060bff7325b1b4bf9b997685b7 Mon Sep 17 00:00:00 2001 From: Leo Hemsted Date: Thu, 20 Dec 2018 16:01:39 +0000 Subject: [PATCH] log more info when we receive multiple delivery callbacks for one notification Previously, we logged a warning containing the notification reference and new status. However it wasn't a great message - this new one includes the notification id, the old status, the time difference and more. This separates out logs for callbacks for notifications we don't know (error level) and duplicates (info level). --- app/dao/notifications_dao.py | 62 +++++++++++++------ .../notifications_ses_callback.py | 3 - app/notifications/process_client_response.py | 4 -- 3 files changed, 44 insertions(+), 25 deletions(-) diff --git a/app/dao/notifications_dao.py b/app/dao/notifications_dao.py index f27190ad3..d683cb636 100644 --- a/app/dao/notifications_dao.py +++ b/app/dao/notifications_dao.py @@ -15,7 +15,7 @@ from notifications_utils.recipients import ( ) from notifications_utils.statsd_decorators import statsd from notifications_utils.timezones import convert_utc_to_bst -from sqlalchemy import (desc, func, or_, asc) +from sqlalchemy import (desc, func, asc) from sqlalchemy.orm import joinedload from sqlalchemy.sql import functions from sqlalchemy.sql.expression import case @@ -144,17 +144,23 @@ def _update_notification_status(notification, status): @statsd(namespace="dao") @transactional def update_notification_status_by_id(notification_id, status, sent_by=None): - notification = Notification.query.with_for_update().filter( - Notification.id == notification_id, - or_( - Notification.status == NOTIFICATION_CREATED, - Notification.status == NOTIFICATION_SENDING, - Notification.status == NOTIFICATION_PENDING, - Notification.status == NOTIFICATION_SENT, - Notification.status == NOTIFICATION_PENDING_VIRUS_CHECK - )).first() + notification = Notification.query.with_for_update().filter(Notification.id == notification_id).first() if not notification: + current_app.logger.error('notification not found for id {} (update to status {})'.format( + notification_id, + status + )) + return None + + if notification.status not in { + NOTIFICATION_CREATED, + NOTIFICATION_SENDING, + NOTIFICATION_PENDING, + NOTIFICATION_SENT, + NOTIFICATION_PENDING_VIRUS_CHECK + }: + _duplicate_update_warning(notification, status) return None if notification.international and not country_records_delivery(notification.phone_prefix): @@ -170,15 +176,19 @@ def update_notification_status_by_id(notification_id, status, sent_by=None): @statsd(namespace="dao") @transactional def update_notification_status_by_reference(reference, status): - notification = Notification.query.filter( - Notification.reference == reference, - or_( - Notification.status == NOTIFICATION_SENDING, - Notification.status == NOTIFICATION_PENDING, - Notification.status == NOTIFICATION_SENT - )).first() + # this is used to update letters and emails + notification = Notification.query.filter(Notification.reference == reference).first() - if not notification or notification.status == NOTIFICATION_SENT: + if not notification: + current_app.logger.error('notification not found for reference {} (update to {})'.format(reference, status)) + return None + + if notification.status not in { + NOTIFICATION_SENDING, + NOTIFICATION_PENDING, + NOTIFICATION_SENT, + }: + _duplicate_update_warning(notification, status) return None return _update_notification_status( @@ -693,3 +703,19 @@ def guess_notification_type(search_term): return EMAIL_TYPE else: return SMS_TYPE + + +def _duplicate_update_warning(notification, status): + current_app.logger.info( + ( + 'Duplicate callback received. Notification id {id} received a status update to {new_status}' + '{time_diff} after being set to {old_status}. {type} sent by {sent_by}' + ).format( + id=notification.id, + old_status=notification.status, + new_status=status, + time_diff=datetime.utcnow() - notification.sent_at, + type=notification.notification_type, + sent_by=notification.sent_by + ) + ) diff --git a/app/notifications/notifications_ses_callback.py b/app/notifications/notifications_ses_callback.py index e90cfeced..d75abcd4e 100644 --- a/app/notifications/notifications_ses_callback.py +++ b/app/notifications/notifications_ses_callback.py @@ -61,9 +61,6 @@ def process_ses_response(ses_request): notification_status ) if not notification: - warning = "SES callback failed: notification either not found or already updated " \ - "from sending. Status {} for notification reference {}".format(notification_status, reference) - current_app.logger.warning(warning) return if not aws_response_dict['success']: diff --git a/app/notifications/process_client_response.py b/app/notifications/process_client_response.py index d45c3cc92..3de60c587 100644 --- a/app/notifications/process_client_response.py +++ b/app/notifications/process_client_response.py @@ -81,10 +81,6 @@ def _process_for_status(notification_status, client_name, provider_reference): sent_by=client_name.lower() ) if not notification: - current_app.logger.warning("{} callback failed: notification {} either not found or already updated " - "from sending. Status {}".format(client_name, - provider_reference, - notification_status)) return statsd_client.incr('callback.{}.{}'.format(client_name.lower(), notification_status))