diff --git a/app/notifications/process_client_response.py b/app/notifications/process_client_response.py index 8f7690b3c..edd152165 100644 --- a/app/notifications/process_client_response.py +++ b/app/notifications/process_client_response.py @@ -1,4 +1,6 @@ import uuid + +from datetime import datetime from flask import current_app from app import statsd_client @@ -54,7 +56,8 @@ def process_sms_client_response(status, reference, client_name): notification_success = response_dict['success'] # record stats - if not notifications_dao.update_notification_status_by_id(reference, notification_status): + notification = notifications_dao.update_notification_status_by_id(reference, notification_status) + if not notification: status_error = "{} callback failed: notification {} either not found or already updated " \ "from sending. Status {}".format(client_name, reference, @@ -68,5 +71,9 @@ def process_sms_client_response(status, reference, client_name): notification_status_message)) statsd_client.incr('callback.{}.{}'.format(client_name.lower(), notification_status)) + statsd_client.timing( + 'callback.{}.elapsed-time'.format(client_name.lower()), + (datetime.utcnow() - notification.sent_at) + ) success = "{} callback succeeded. reference {} updated".format(client_name, reference) return success, errors diff --git a/app/notifications/rest.py b/app/notifications/rest.py index 35e55f2ed..fa8463c68 100644 --- a/app/notifications/rest.py +++ b/app/notifications/rest.py @@ -79,10 +79,11 @@ def process_ses_response(): try: reference = ses_message['mail']['messageId'] - if not notifications_dao.update_notification_status_by_reference( - reference, - notification_status - ): + notification = notifications_dao.update_notification_status_by_reference( + reference, + notification_status + ) + if not notification: error = "SES callback failed: notification either not found or already updated " \ "from sending. Status {}".format(notification_status) raise InvalidRequest(error, status_code=404) @@ -96,6 +97,7 @@ def process_ses_response(): ) statsd_client.incr('callback.ses.{}'.format(notification_status)) + statsd_client.timing('callback.ses.elapsed-time', (datetime.utcnow() - notification.sent_at)) return jsonify( result="success", message="SES callback succeeded" ), 200 @@ -231,8 +233,8 @@ def send_notification(notification_type): raise InvalidRequest(errors, status_code=400) if ( - template_object.template_type == SMS_TYPE and - template_object.replaced_content_count > current_app.config.get('SMS_CHAR_COUNT_LIMIT') + template_object.template_type == SMS_TYPE and + template_object.replaced_content_count > current_app.config.get('SMS_CHAR_COUNT_LIMIT') ): char_count = current_app.config.get('SMS_CHAR_COUNT_LIMIT') message = 'Content has a character count greater than the limit of {}'.format(char_count) @@ -240,14 +242,14 @@ def send_notification(notification_type): raise InvalidRequest(errors, status_code=400) if all(( - api_user.key_type != KEY_TYPE_TEST, - service.restricted or api_user.key_type == KEY_TYPE_TEAM, - not allowed_to_send_to( - notification['to'], - itertools.chain.from_iterable( - [user.mobile_number, user.email_address] for user in service.users + api_user.key_type != KEY_TYPE_TEST, + service.restricted or api_user.key_type == KEY_TYPE_TEAM, + not allowed_to_send_to( + notification['to'], + itertools.chain.from_iterable( + [user.mobile_number, user.email_address] for user in service.users + ) ) - ) )): if (api_user.key_type == KEY_TYPE_TEAM): message = 'Can’t send to this recipient using a team-only API key' diff --git a/tests/app/conftest.py b/tests/app/conftest.py index 5dcdf3be8..1346d1dca 100644 --- a/tests/app/conftest.py +++ b/tests/app/conftest.py @@ -342,6 +342,7 @@ def sample_notification(notify_db, status='created', reference=None, created_at=None, + sent_at=None, billable_units=1, create=True, personalisation=None, @@ -375,6 +376,7 @@ def sample_notification(notify_db, 'status': status, 'reference': reference, 'created_at': created_at, + 'sent_at': sent_at, 'billable_units': billable_units, 'personalisation': personalisation, 'notification_type': template.template_type, diff --git a/tests/app/notifications/rest/test_callbacks.py b/tests/app/notifications/rest/test_callbacks.py index 7364145d2..6ec67e97f 100644 --- a/tests/app/notifications/rest/test_callbacks.py +++ b/tests/app/notifications/rest/test_callbacks.py @@ -1,6 +1,9 @@ import uuid +from datetime import datetime from flask import json +from freezegun import freeze_time +from mock import call import app.celery.tasks from app.dao.notifications_dao import ( @@ -441,29 +444,38 @@ def test_ses_callback_should_update_notification_status( notify_api, notify_db, notify_db_session, - sample_email_template): + sample_email_template, + mocker): with notify_api.test_request_context(): with notify_api.test_client() as client: - notification = create_sample_notification( - notify_db, - notify_db_session, - template=sample_email_template, - reference='ref', - status='sending' - ) + with freeze_time('2001-01-01T12:00:00'): + mocker.patch('app.statsd_client.incr') + mocker.patch('app.statsd_client.timing') + notification = create_sample_notification( + notify_db, + notify_db_session, + template=sample_email_template, + reference='ref', + status='sending', + sent_at=datetime.utcnow() + ) - assert get_notification_by_id(notification.id).status == 'sending' + assert get_notification_by_id(notification.id).status == 'sending' - response = client.post( - path='/notifications/email/ses', - data=ses_notification_callback(), - headers=[('Content-Type', 'text/plain; charset=UTF-8')] - ) - json_resp = json.loads(response.get_data(as_text=True)) - assert response.status_code == 200 - assert json_resp['result'] == 'success' - assert json_resp['message'] == 'SES callback succeeded' - assert get_notification_by_id(notification.id).status == 'delivered' + response = client.post( + path='/notifications/email/ses', + data=ses_notification_callback(), + headers=[('Content-Type', 'text/plain; charset=UTF-8')] + ) + json_resp = json.loads(response.get_data(as_text=True)) + assert response.status_code == 200 + assert json_resp['result'] == 'success' + assert json_resp['message'] == 'SES callback succeeded' + assert get_notification_by_id(notification.id).status == 'delivered' + app.statsd_client.timing.assert_any_call( + "callback.ses.elapsed-time", datetime.utcnow() - notification.sent_at + ) + app.statsd_client.incr.assert_any_call("callback.ses.delivered") def test_ses_callback_should_update_multiple_notification_status_sent( @@ -600,35 +612,54 @@ def test_ses_callback_should_set_status_to_permanent_failure(notify_api, assert get_notification_by_id(notification.id).status == 'permanent-failure' -def test_process_mmg_response_records_statsd(notify_api, sample_notification, mocker): +def test_process_mmg_response_records_statsd(notify_db, notify_db_session,notify_api, sample_notification, mocker): with notify_api.test_client() as client: - mocker.patch('app.statsd_client.incr') - data = json.dumps({"reference": "mmg_reference", - "CID": str(sample_notification.id), - "MSISDN": "447777349060", - "status": "3", - "deliverytime": "2016-04-05 16:01:07"}) + with freeze_time('2001-01-01T12:00:00'): - client.post(path='notifications/sms/mmg', - data=data, - headers=[('Content-Type', 'application/json')]) - app.statsd_client.incr.assert_any_call("callback.mmg.delivered") + mocker.patch('app.statsd_client.incr') + mocker.patch('app.statsd_client.timing') + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) + + data = json.dumps({"reference": "mmg_reference", + "CID": str(notification.id), + "MSISDN": "447777349060", + "status": "3", + "deliverytime": "2016-04-05 16:01:07"}) + + client.post(path='notifications/sms/mmg', + data=data, + headers=[('Content-Type', 'application/json')]) + + app.statsd_client.incr.assert_any_call("callback.mmg.delivered") + app.statsd_client.timing.assert_any_call( + "callback.mmg.elapsed-time", datetime.utcnow() - notification.sent_at + ) def test_firetext_callback_should_record_statsd(notify_api, notify_db, notify_db_session, mocker): with notify_api.test_request_context(): with notify_api.test_client() as client: - mocker.patch('app.statsd_client.incr') - notification = create_sample_notification(notify_db, notify_db_session, status='sending') + with freeze_time('2001-01-01T12:00:00'): - client.post( - path='/notifications/sms/firetext', - data='mobile=441234123123&status=0&time=2016-03-10 14:17:00&code=101&reference={}'.format( - notification.id - ), - headers=[('Content-Type', 'application/x-www-form-urlencoded')]) + mocker.patch('app.statsd_client.incr') + mocker.patch('app.statsd_client.timing') + notification = create_sample_notification( + notify_db, notify_db_session, status='sending', sent_at=datetime.utcnow() + ) - app.statsd_client.incr.assert_any_call("callback.firetext.delivered") + client.post( + path='/notifications/sms/firetext', + data='mobile=441234123123&status=0&time=2016-03-10 14:17:00&code=101&reference={}'.format( + notification.id + ), + headers=[('Content-Type', 'application/x-www-form-urlencoded')]) + + app.statsd_client.timing.assert_any_call( + "callback.firetext.elapsed-time", datetime.utcnow() - notification.sent_at + ) + app.statsd_client.incr.assert_any_call("callback.firetext.delivered") def ses_notification_callback(ref='ref'):